Hi Gabor,
It look to me like some library mismatch or some missing package from the Xrootd side. At this point the problem that you are hitting has nothing to do with the TPC setup.
Can you please provide the output of the following commands?
locate libXrdSec-4.so
rpm -qa | grep xrootd
Thanks,
Elvin
Hi Elvin,
This is the output:
[root@eos-mgm1 ~]# locate libXrdSec-4.so
/opt/eos/xrootd/lib64/libXrdSec-4.so
/usr/lib64/libXrdSec-4.so
[root@eos-mgm1 ~]# rpm -qa | grep xrootd
xrootd-server-4.11.3-1.el7.x86_64
xrootd-client-devel-4.11.3-1.el7.x86_64
eos-xrootd-4.11.3-1.el7.cern.x86_64
xrootd-client-libs-4.11.3-1.el7.x86_64
xrootd-server-libs-4.11.3-1.el7.x86_64
xrootd-selinux-4.11.3-1.el7.noarch
xrootd-devel-4.11.3-1.el7.x86_64
xrootd-server-devel-4.11.3-1.el7.x86_64
xrootd-private-devel-4.11.3-1.el7.x86_64
xrootd-alicetokenacc-1.3.1-1.x86_64
xrootd-libs-4.11.3-1.el7.x86_64
xrootd-4.11.3-1.el7.x86_64
xrootd-client-4.11.3-1.el7.x86_64
Is it maybe possible that there is some discrepancy between the two libXrdSec?
Thanks,
Gabor
Hi,
so, I didn’t find any reason why it shouldn’t work. Is it maybe possible that my problem is related to this issue, i.e. I have incompatible eos-xrootd and eos-server versions? Could you please give me some hint which versions should I install together?
Thanks,
Gabor
Hi Gabor,
The version of XRootD that you have installed is the correct one i.e. it should be compatible with EOS 4.7.7. Can you restart the MGM and send me the full log? Also can you send me your /etc/xrd.cf.mgm file?
Thanks,
Elvin
Hi Elvin,
this is the full xrdlog after a restart:
201130 12:08:02 31814 Starting on Linux 3.10.0-1127.19.1.el7.x86_64
Copr. 2004-2012 Stanford University, xrd version v4.11.3
++++++ xrootd mgm@eos-mgm1.alice-af.wigner.hu initialization started.
Config using configuration file /etc/xrd.cf.mgm
=====> all.sitename ALICE::KFKI::EOS
=====> xrd.sched mint 8 maxt 256 idle 64
Config maximum number of connections restricted to 65000
Copr. 2012 Stanford University, xrootd protocol 4.0.0 version v4.11.3
++++++ xrootd protocol initialization started.
=====> xrootd.fslib libXrdEosMgm.so
=====> xrootd.seclib libXrdSec.so
=====> xrootd.async off nosf
=====> xrootd.chksum adler32
=====> all.export / nolock
Config exporting /
Plugin loaded
++++++ Authentication system initialization started.
Plugin loaded
=====> sec.protocol unix
Plugin loaded
=====> sec.protocol sss -c /etc/eos.keytab -s /etc/eos.keytab
=====> sec.protbind localhost.localdomain unix sss
=====> sec.protbind localhost unix sss
201130 12:08:02 31814 sec_Config: protbind krb5 protocol not previously defined.
=====> sec.protbind * only krb5
Config 5 authentication directives processed in /etc/xrd.cf.mgm
------ Authentication system initialization failed.
Config Unable to create security framework via libXrdSec.so
201130 12:08:02 31814 XrootdConfig: Unable to load security system.
------ xrootd protocol initialization failed.
201130 12:08:02 31814 XrdProtocol: Protocol xrootd could not be loaded
------ xrootd mgm@eos-mgm1.alice-af.wigner.hu:-1 initialization failed.
And this is the /etc/xrd.cf.mgm:
###########################################################
set myName = ALICE::KFKI::EOS
all.sitename $myName
###########################################################
xrootd.fslib libXrdEosMgm.so
xrootd.seclib libXrdSec.so
xrootd.async off nosf
xrootd.chksum adler32
###########################################################
xrd.sched mint 8 maxt 256 idle 64
###########################################################
all.export / nolock
all.role manager
###########################################################
oss.fdlimit 16384 32768
###########################################################
# UNIX authentication
sec.protocol unix
# SSS authentication
sec.protocol sss -c /etc/eos.keytab -s /etc/eos.keytab
# KRB authentication
#sec.protocol krb5 -exptkn:/var/eos/auth/krb5#<uid> host/<host>@CERN.CH
# sec.protocol krb5 host/<host>@CERN.CH
# GSI authentication
#sec.protocol gsi -crl:0 -cert:/etc/grid-security/daemon/hostcert.pem -key:/etc/grid-security/daemon/hostkey.pem -gridmap:/etc/grid-security/grid-mapfile -d:0 -gmapopt:2 -vomsat:1 -moninfo:1 -exppxy:/var/eos/auth/gsi#<uid>
# sec.protocol gsi -crl:0 -cert:/etc/grid-security/daemon/hostcert.pem -key:/etc/grid-security/daemon/hostkey.pem -gridmap:/etc/grid-security/grid-mapfile -d:0 -gmapopt:2 -vomsat:1 -moninfo:1
###########################################################
sec.protbind localhost.localdomain unix sss
sec.protbind localhost unix sss
sec.protbind * only krb5 gsi sss unix
###########################################################
mgmofs.fs /
mgmofs.targetport 1095
mgmofs.centraldrain true
mgmofs.authlib /usr/lib64/libXrdAliceTokenAcc.so
mgmofs.authorize 1
###########################################################
## configure bypass and prefix for ALICE SE
############################################################
alicetokenacc.noauthzhost localhost
alicetokenacc.noauthzhost localhost.localdomain
alicetokenacc.truncateprefix /eos/alice/grid
###########################################################
#mgmofs.trace all debug
# this URL can be overwritten by EOS_BROKER_URL defined in /etc/sysconfig/eos
mgmofs.broker root://localhost:1097//eos/
# this name can be overwritten by EOS_INSTANCE_NAME defined in /etc/sysconfig/eos
mgmofs.instance eosalice
# configuration, namespace , transfer and authentication export directory
mgmofs.configdir /var/eos/config
mgmofs.metalog /var/eos/md
mgmofs.txdir /var/eos/tx
mgmofs.authdir /var/eos/auth
mgmofs.archivedir /var/eos/archive
# report store path
mgmofs.reportstorepath /var/eos/report
# this defines the default config to load
mgmofs.autoloadconfig default
#-------------------------------------------------------------------------------
# Config Engine Configuration
#-------------------------------------------------------------------------------
mgmofs.cfgtype file
mgmofs.nslib /usr/lib64/libEosNsInMemory.so
Thanks for your help!
Gabor
Hi Gabor,
Ok, so the actual problem in your configuration is that you require sec.protbind to krb5 but you never load the krb5 library - notice that sec.protocol krb5 is commented. Once you do this, restart the MGM and it should work just fine.
Cheers,
Elvin
Hi Elvin,
My mistake, the krb5 was misconfigured indeed. Thanks, it seems to work now.
Now I’ll check the TPC setup (which is my main goal). I configured it according to the link in the first post.
Thanks again,
Gabor
Hi Elvin,
So, I would like to pick up this thread and ask for your help again, and try understand the mechanism. Since my last post I still have issues with the TPC setup. These are the error messages I get:
xrdcp (TPC==1) exited with exit code 54: [ERROR] Server responded with an error: [3012] sync - TPC open failed for src_url=root://p06636710h76580.cern.ch:1095//04/36435/05422528-a162-11e8-b5f9-a310691b2def?fst.readahead=true
and the error.log is filled with these:
210114 17:23:45 time=1610645025.908619 func=fileOpen level=ERROR logid=3daab5f0-568d-11eb-af4c-00259074c8e8 unit=fst@eos-fst07.alice-af.wigner.hu:1095 tid=00007f969f1e4700 source=XrdIo:233 tident=<service> sec= uid=0 gid=0 name= geo="" error= "open failed url=root://p06636710h76580.cern.ch:1095//04/36435/05422528-a162-11e8-b5f9-a310691b2def?fst.readahead=true&fst.valid=1610645078&tpc.key=3a274c52cdbb62d560007e1a&tpc.org=monalisa.25301@pcalimonitor.cern.ch, errno=0, errc=103, msg=[FATAL] Socket timeout"
210114 17:23:45 time=1610645025.908693 func=DoTpcTransfer level=ERROR logid=3daab5f0-568d-11eb-af4c-00259074c8e8 unit=fst@eos-fst07.alice-af.wigner.hu:1095 tid=00007f969f1e4700 source=XrdFstOfsFile:3159 tident=monalisa.25301:118@pcalimonitor.cern.ch sec= uid=99 gid=99 name=nobody geo="" msg="TPC open failed for url=root://p06636710h76580.cern.ch:1095//04/36435/05422528-a162-11e8-b5f9-a310691b2def?fst.readahead=true cgi=tpc.key=3a274c52cdbb62d560007e1a&tpc.org=monalisa.25301@pcalimonitor.cern.ch"
210114 17:33:26 time=1610645606.778135 func=open level=ERROR logid=unknown unit=fst@eos-fst02.alice-af.wigner.hu:1095 tid=00007f1c19ff2700 source=XrdFstOfsFile:134 tident=nobody sec=unix uid=0 gid=0 name=nobody geo="" msg="failed while processing TPC/open opaque"
I already tried a few things, but I have a lack of understanding and don’t really know how should I solve this, so I appreciate any help. Currently this is the /etc/xrd.cf.mgm:
###########################################################
set myName = ALICE::KFKI::EOS
all.sitename $myName
###########################################################
xrootd.fslib libXrdEosMgm.so
xrootd.seclib libXrdSec.so
xrootd.async off nosf
xrootd.chksum adler32
###########################################################
xrd.sched mint 8 maxt 256 idle 64
###########################################################
all.export / nolock
all.role manager
###########################################################
oss.fdlimit 16384 32768
###########################################################
# UNIX authentication
sec.protocol unix
# SSS authentication
sec.protocol sss -c /etc/eos.keytab -s /etc/eos.keytab
# KRB authentication
# sec.protocol krb5 -exptkn:/var/eos/auth/krb5#<uid> host/<host>@CERN.CH
# sec.protocol krb5 host/<host>@CERN.CH
# GSI authentication
sec.protocol gsi -crl:0 -cert:/etc/grid-security/daemon/hostcert.pem -key:/etc/grid-security/daemon/hostkey.pem -gridmap:/etc/grid-security/grid-mapfile -d:0 -gmapopt:2 -vomsat:1 -moninfo:1 -exppxy:/var/eos/auth/gsi#<uid>
# sec.protocol gsi -crl:0 -cert:/etc/grid-security/daemon/hostcert.pem -key:/etc/grid-security/daemon/hostkey.pem -gridmap:/etc/grid-security/grid-mapfile -d:0 -gmapopt:2 -vomsat:1 -moninfo:1
###########################################################
sec.protbind localhost.localdomain unix sss
sec.protbind localhost unix sss
sec.protbind * only sss unix gsi
###########################################################
mgmofs.fs /
mgmofs.targetport 1095
mgmofs.centraldrain true
mgmofs.authlib /usr/lib64/libXrdAliceTokenAcc.so
mgmofs.authorize 1
###########################################################
## configure bypass and prefix for ALICE SE
############################################################
alicetokenacc.noauthzhost localhost
alicetokenacc.noauthzhost localhost.localdomain
alicetokenacc.truncateprefix /eos/alice/grid
###########################################################
#mgmofs.trace all debug
# this URL can be overwritten by EOS_BROKER_URL defined in /etc/sysconfig/eos
mgmofs.broker root://localhost:1097//eos/
# this name can be overwritten by EOS_INSTANCE_NAME defined in /etc/sysconfig/eos
mgmofs.instance eosalice
# configuration, namespace , transfer and authentication export directory
mgmofs.configdir /var/eos/config
mgmofs.metalog /var/eos/md
mgmofs.txdir /var/eos/tx
mgmofs.authdir /var/eos/auth
mgmofs.archivedir /var/eos/archive
# report store path
mgmofs.reportstorepath /var/eos/report
# this defines the default config to load
mgmofs.autoloadconfig default
#-------------------------------------------------------------------------------
# Config Engine Configuration
#-------------------------------------------------------------------------------
mgmofs.cfgtype file
# this has to be defined if we have a failover configuration via alias - can be overwritten by EOS_MGM_ALIAS in /etc/sysconfig/eos
#mgmofs.alias eosdev.cern.ch
#-------------------------------------------------------------------------------
# Configuration for the authentication plugin EosAuth
#-------------------------------------------------------------------------------
# Set the number of authentication worker threads running on the MGM
#mgmofs.auththreads 10
# Set the front end port number for incoming authentication requests
#mgmofs.authport 15555
###########################################################
# Set the FST gateway host and port
# mgmofs.fstgw someproxy.cern.ch:3001
#-------------------------------------------------------------------------------
# Configuration for the authentication plugin EosAuth
#-------------------------------------------------------------------------------
# Set the number of authentication worker threads running on the MGM
#mgmofs.auththreads 10
# Set the front end port number for incoming authentication requests
#mgmofs.authport 15555
#-------------------------------------------------------------------------------
# Set the namespace plugin implementation
#-------------------------------------------------------------------------------
mgmofs.nslib /usr/lib64/libEosNsInMemory.so
#mgmofs.nslib /usr/lib64/libEosNsQuarkdb.so
# Quarkdb custer configuration used for the namespace
#mgmofs.qdbcluster localhost:7777
#mgmofs.qdbpassword_file /etc/eos.keytab
#-------------------------------------------------------------------------------
# Configuration for the MGM workflow engine
#-------------------------------------------------------------------------------
# The SSI protocol buffer endpoint for notification messages from "proto" workflow actions
#mgmofs.protowfendpoint HOSTNAME.2NDLEVEL.TOPLEVEL:10955
#mgmofs.protowfresource /SSI_RESOURCE
#-------------------------------------------------------------------------------
# Confguration parameters for tape
#-------------------------------------------------------------------------------
#mgmofs.tapeenabled false
#mgmofs.prepare.dest.space default
#-------------------------------------------------------------------------------
# Configuration for the tape aware garbage collector
#-------------------------------------------------------------------------------
# EOS spaces for which the tape aware garbage collector should be enabled
#mgmofs.tgc.enablespace space1 space2 ...
# TPC setups
ofs.tpc redirect delegated eos-gateway-node.cern.ch:1094
# Load and enable HTTP(S) access on port 9000 on the current instance
xrd.protocol XrdHttp:9000 /usr/lib64/libXrdHttp-4.so
# Directory containing CA certificates to be used by the server
http.cadir /etc/grid-security/certificates/
# File containing the x509 server certificate
http.cert /etc/grid-security/daemon//hostcert.pem
# File containing the x509 server private key
http.key /etc/grid-security/daemon/hostkey.pem
# Path to the "grid map file" to be used for mapping users to specific identities
http.gridmap /etc/grid-security/grid-mapfile
# Load the XrdHttpVOMS security extractor plugin that is able to deal with
# proxy certificats and VOMS credentials
# --> VOMS-4?
http.secxtractor libXrdHttpVOMS-4.so
# Optionally enable tracing on the HTTP plugin
http.trace all
# Load the XrdTpc external handler which deals only with COPY and OPTIONS http
# verbs and provides the default HTTP TPC functionality
http.exthandler xrdtpc /usr/lib64/libXrdHttpTPC-4.so
# Load the EOS specific HTTP external handler libEosMgmHttp.so and also specify
# the option is HTTP traffic is to be redirected to HTTP(S)
http.exthandler EosMgmHttp /usr/lib64/libEosMgmHttp-4.so eos::mgm::http::redirect-to-https=0
# The following two external library plugins are used to provide support for
# token based authentication with Macaroons and SciTokens. Presence of the
# second library is optional. When the SciTokens library is present and the
# XrdMacaroons can not deal with the request then this is delegated to the
# SciTokens library.
# Note: this is subject to change in future versions!
mgmofs.macaroonslib /usr/lib64/libXrdMacaroons-4.so /opt/eos/lib64/libXrdAccSciTokens-4.so
# Base64-encoded secret key used for generating macroons. A simple way to
# generate such a secret key is to use the following command:
# openssl rand -base64 -out /etc/eos.macaroon.secret 64
macaroons.secretkey /etc/eos.macaroon.secret
# Optionally enable tracing for the XrdMacaroons plugin
macaroons.trace all
# Mandatory sitename configuration for the XrdMacaroons library which is also
# embedded in the macaroons attributes
all.sitename $myName
And on the fst, the /etc/xrd.cf.fst:
###########################################################
set MGM=$EOS_MGM_ALIAS
###########################################################
#
###########################################################
# set myName = ALICE::KFKI::EOS
# all.sitename $myName
xrootd.fslib -2 libXrdEosFst.so
xrootd.async off nosf
xrd.network keepalive
xrootd.redirect $(MGM):1094 chksum
###########################################################
xrootd.seclib libXrdSec.so
sec.protocol unix
sec.protocol sss -c /etc/eos.keytab -s /etc/eos.keytab
sec.protbind * only unix sss
###########################################################
all.export / nolock
all.trace none
all.manager localhost 2131
#ofs.trace open
###########################################################
xrd.port 1095
ofs.persist off
ofs.osslib libEosFstOss.so
ofs.tpc pgm /usr/bin/xrdcp
###########################################################
# this URL can be overwritten by EOS_BROKER_URL defined /etc/sysconfig/xrd
fstofs.broker root://eos-mgm1.alice-af.wigner.hu:1097//eos/
fstofs.autoboot true
fstofs.quotainterval 10
fstofs.metalog /var/eos/md/
#fstofs.authdir /var/eos/auth/
#fstofs.trace client
###########################################################
#-------------------------------------------------------------------------------
# Configuration for XrdHttp http(s) service on port 11000
#-------------------------------------------------------------------------------
#if exec xrootd
# xrd.protocol XrdHttp:11000 /usr/lib64/libXrdHttp-4.so
# http.exthandler EosFstHttp /usr/lib64/libEosFstHttp.so none
# http.cert /etc/grid-security/daemon/host.cert
# http.key /etc/grid-security/daemon/privkey.pem
# http.cafile /etc/grid-security/daemon/ca.cert
#fi
xrootd.monitor all flush 60s window 30s dest files info user vobox01.alice-af.wigner.hu:9930
# Enable the XrdHttp plugin and listen on port 9001 for connections
xrd.protocol XrdHttp:9001 /usr/lib64/libXrdHttp-4.so
# Load the libEosFstHttp external handler
http.exthandler EosFstHttp /usr/lib64/libEosFstHttp.so none
# Load the XrdTpc external handler which deals with COPY and OPTIONS http
# verbs and provides the default HTTP TPC functionality
http.exthandler xrdtpc /usr/lib64/libXrdHttpTPC-4.so
# ofs.osslib libXrdPss.so
# ofs.ckslib * libXrdPss.so
# xrootd.chksum adler32
# xrootd.seclib libXrdSec.so
# pss.origin eos-mgm1.alice-af.wigner.hu:1094
# all.export /eos/
# all.adminpath /var/spool/xrootd
# all.pidpath /var/run/xrootd
# sec.protocol gsi -dlgpxy:1 -exppxy:=creds -crl:1 -moninfo:1 -cert:/etc/grid-security/daemon/gridftp-cert.pem -key:/etc/grid-security/daemon/gridftp-key.pem -gridmap:/etc/grid-security/grid-mapfile -d:1 -gmapopt:2
# sec.protbind * gsi
# ofs.tpc autorm fcreds gsi =X509_USER_PROXY ttl 60 60 xfr 9 pgm /usr/local/bin/xrootd-third-party-copy.sh
Thanks,
Gabor
Hi Gabor,
Could you please make sure the following env variable is present in /etc/sysconfig/eos_env?
EOS_FST_NO_SSS_ENFORCEMENT=1
After adding this env variable please restart the FSTs.
Please retry the transfer and post also the command that you use for triggering the TPC transfer.
Thanks,
Elvin
Hi Elvin,
The variable is set everywhere and I did the restart as well. There is a regular ALICE test with a long command and with remote copy that fails, but I performed a local test too (however, I’m not sure it is a proper way to test the transfer):
[root@eos-mgm1 ~]# xrdcp --tpc only --force -d 3 root://eos-mgm1.alice-af.wigner.hu:1094//eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a root://eos-mgm1.alice-af.wigner.hu:1094//eos/testarea/.
[2021-01-27 11:53:44.311496 +0000][Dump ][App ] Chunk size: 8388608, parallel chunks 4, streams: 1
[2021-01-27 11:53:44.311619 +0000][Dump ][Utility ] URL: root://eos-mgm1.alice-af.wigner.hu:1094//eos/testarea/.
[2021-01-27 11:53:44.311619 +0000][Dump ][Utility ] Protocol: root
[2021-01-27 11:53:44.311619 +0000][Dump ][Utility ] User Name:
[2021-01-27 11:53:44.311619 +0000][Dump ][Utility ] Password:
[2021-01-27 11:53:44.311619 +0000][Dump ][Utility ] Host Name: eos-mgm1.alice-af.wigner.hu
[2021-01-27 11:53:44.311619 +0000][Dump ][Utility ] Port: 1094
[2021-01-27 11:53:44.311619 +0000][Dump ][Utility ] Path: /eos/testarea/.
[2021-01-27 11:53:44.311655 +0000][Dump ][Utility ] URL: root://eos-mgm1.alice-af.wigner.hu:1094//eos/testarea/.
[2021-01-27 11:53:44.311655 +0000][Dump ][Utility ] Protocol: root
[2021-01-27 11:53:44.311655 +0000][Dump ][Utility ] User Name:
[2021-01-27 11:53:44.311655 +0000][Dump ][Utility ] Password:
[2021-01-27 11:53:44.311655 +0000][Dump ][Utility ] Host Name: eos-mgm1.alice-af.wigner.hu
[2021-01-27 11:53:44.311655 +0000][Dump ][Utility ] Port: 1094
[2021-01-27 11:53:44.311655 +0000][Dump ][Utility ] Path: /eos/testarea/.
[2021-01-27 11:53:44.311693 +0000][Dump ][Utility ] URL: root://eos-mgm1.alice-af.wigner.hu:1094//eos/testarea/.
[2021-01-27 11:53:44.311693 +0000][Dump ][Utility ] Protocol: root
[2021-01-27 11:53:44.311693 +0000][Dump ][Utility ] User Name:
[2021-01-27 11:53:44.311693 +0000][Dump ][Utility ] Password:
[2021-01-27 11:53:44.311693 +0000][Dump ][Utility ] Host Name: eos-mgm1.alice-af.wigner.hu
[2021-01-27 11:53:44.311693 +0000][Dump ][Utility ] Port: 1094
[2021-01-27 11:53:44.311693 +0000][Dump ][Utility ] Path: /eos/testarea/.
[2021-01-27 11:53:44.311726 +0000][Dump ][Utility ] URL: root://eos-mgm1.alice-af.wigner.hu:1094//eos/testarea/.
[2021-01-27 11:53:44.311726 +0000][Dump ][Utility ] Protocol: root
[2021-01-27 11:53:44.311726 +0000][Dump ][Utility ] User Name:
[2021-01-27 11:53:44.311726 +0000][Dump ][Utility ] Password:
[2021-01-27 11:53:44.311726 +0000][Dump ][Utility ] Host Name: eos-mgm1.alice-af.wigner.hu
[2021-01-27 11:53:44.311726 +0000][Dump ][Utility ] Port: 1094
[2021-01-27 11:53:44.311726 +0000][Dump ][Utility ] Path: /eos/testarea/.
[2021-01-27 11:53:44.311775 +0000][Dump ][FileSystem ] [0xfc853a40@eos-mgm1.alice-af.wigner.hu:1094] Sending kXR_stat (path: /eos/testarea/., flags: none)
[2021-01-27 11:53:44.311806 +0000][Debug ][Poller ] Available pollers: built-in
[2021-01-27 11:53:44.311815 +0000][Debug ][Poller ] Attempting to create a poller according to preference: built-in
[2021-01-27 11:53:44.311825 +0000][Debug ][Poller ] Creating poller: built-in
[2021-01-27 11:53:44.311841 +0000][Debug ][Poller ] Creating and starting the built-in poller...
[2021-01-27 11:53:44.312057 +0000][Debug ][Poller ] Using 1 poller threads
[2021-01-27 11:53:44.312071 +0000][Debug ][TaskMgr ] Starting the task manager...
[2021-01-27 11:53:44.312111 +0000][Debug ][TaskMgr ] Task manager started
[2021-01-27 11:53:44.312123 +0000][Debug ][JobMgr ] Starting the job manager...
[2021-01-27 11:53:44.312231 +0000][Debug ][JobMgr ] Job manager started, 3 workers
[2021-01-27 11:53:44.312255 +0000][Debug ][TaskMgr ] Registering task: "FileTimer task" to be run at: [2021-01-27 11:53:44 +0000]
[2021-01-27 11:53:44.312269 +0000][Dump ][XRootD ] [eos-mgm1.alice-af.wigner.hu:1094] Sending message kXR_stat (path: /eos/testarea/., flags: none)
[2021-01-27 11:53:44.312320 +0000][Dump ][Utility ] URL: eos-mgm1.alice-af.wigner.hu:1094
[2021-01-27 11:53:44.312320 +0000][Dump ][Utility ] Protocol: root
[2021-01-27 11:53:44.312320 +0000][Dump ][Utility ] User Name:
[2021-01-27 11:53:44.312320 +0000][Dump ][Utility ] Password:
[2021-01-27 11:53:44.312320 +0000][Dump ][Utility ] Host Name: eos-mgm1.alice-af.wigner.hu
[2021-01-27 11:53:44.312320 +0000][Dump ][Utility ] Port: 1094
[2021-01-27 11:53:44.312320 +0000][Dump ][Utility ] Path:
[2021-01-27 11:53:44.312354 +0000][Debug ][PostMaster ] Creating new channel to: eos-mgm1.alice-af.wigner.hu:1094 1 stream(s)
[2021-01-27 11:53:44.312395 +0000][Debug ][PostMaster ] [eos-mgm1.alice-af.wigner.hu:1094 #0] Stream parameters: Network Stack: IPAuto, Connection Window: 120, ConnectionRetry: 5, Stream Error Window: 1800
[2021-01-27 11:53:44.312481 +0000][Debug ][TaskMgr ] Registering task: "TickGeneratorTask for: eos-mgm1.alice-af.wigner.hu:1094" to be run at: [2021-01-27 11:53:59 +0000]
[2021-01-27 11:53:44.312502 +0000][Debug ][ExDbgMsg ] [eos-mgm1.alice-af.wigner.hu:1094] MsgHandler created: 0x1a783a0 (message: kXR_stat (path: /eos/testarea/., flags: none) ).
[2021-01-27 11:53:44.312524 +0000][Dump ][PostMaster ] [eos-mgm1.alice-af.wigner.hu:1094 #0] Sending message kXR_stat (path: /eos/testarea/., flags: none) (0x1a72f60) through substream 0 expecting answer at 0
[2021-01-27 11:53:44.312618 +0000][Debug ][PostMaster ] [eos-mgm1.alice-af.wigner.hu:1094] Found 1 address(es): [::ffff:172.16.152.16]:1094
[2021-01-27 11:53:44.312667 +0000][Debug ][AsyncSock ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Attempting connection to [::ffff:172.16.152.16]:1094
[2021-01-27 11:53:44.312765 +0000][Debug ][Poller ] Adding socket 0x1a780c0 to the poller
[2021-01-27 11:53:44.312893 +0000][Debug ][AsyncSock ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Async connection call returned
[2021-01-27 11:53:44.313065 +0000][Debug ][XRootDTransport ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Sending out the initial hand shake + kXR_protocol
[2021-01-27 11:53:44.313153 +0000][Dump ][AsyncSock ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Wrote a message: (0x8000950), 44 bytes
[2021-01-27 11:53:44.313217 +0000][Dump ][XRootDTransport ] [msg: 0x8000950] Expecting 8 bytes of message body
[2021-01-27 11:53:44.313229 +0000][Dump ][AsyncSock ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Received message header, size: 8
[2021-01-27 11:53:44.313248 +0000][Dump ][AsyncSock ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Received a message of 16 bytes
[2021-01-27 11:53:44.313268 +0000][Debug ][XRootDTransport ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Got the server hand shake response (type: manager [], protocol version 400)
[2021-01-27 11:53:44.313286 +0000][Dump ][XRootDTransport ] [msg: 0x8000950] Expecting 8 bytes of message body
[2021-01-27 11:53:44.313297 +0000][Dump ][AsyncSock ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Received message header, size: 8
[2021-01-27 11:53:44.313311 +0000][Dump ][AsyncSock ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Received a message of 16 bytes
[2021-01-27 11:53:44.313326 +0000][Debug ][XRootDTransport ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] kXR_protocol successful (type: manager [], protocol version 400)
[2021-01-27 11:53:44.313543 +0000][Debug ][XRootDTransport ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Sending out kXR_login request, username: root, cgi: ?xrd.cc=hu&xrd.tz=0&xrd.appname=xrdcp&xrd.info=&xrd.hostname=eos-mgm1.alice-af.wigner.hu&xrd.rn=v4.11.3, dual-stack: false, private IPv4: true, private IPv6: false
[2021-01-27 11:53:44.313584 +0000][Dump ][AsyncSock ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Wrote a message: (0x8000a60), 127 bytes
[2021-01-27 11:53:44.313748 +0000][Dump ][XRootDTransport ] [msg: 0x8000950] Expecting 50 bytes of message body
[2021-01-27 11:53:44.313793 +0000][Dump ][AsyncSock ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Received message header, size: 8
[2021-01-27 11:53:44.313809 +0000][Dump ][AsyncSock ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Received a message of 58 bytes
[2021-01-27 11:53:44.313834 +0000][Debug ][XRootDTransport ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Logged in, session: 8a0c00007178000080000000960c0000
[2021-01-27 11:53:44.313846 +0000][Debug ][XRootDTransport ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Authentication is required: &P=unix&P=sss,0.13:/etc/eos.keytab
[2021-01-27 11:53:44.313867 +0000][Debug ][XRootDTransport ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Sending authentication data
[2021-01-27 11:53:44.314654 +0000][Debug ][XRootDTransport ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Trying to authenticate using unix
[2021-01-27 11:53:44.314863 +0000][Dump ][AsyncSock ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Wrote a message: (0x80022f0), 39 bytes
[2021-01-27 11:53:44.315044 +0000][Dump ][XRootDTransport ] [msg: 0x80022f0] Expecting 0 bytes of message body
[2021-01-27 11:53:44.315058 +0000][Dump ][AsyncSock ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Received message header, size: 8
[2021-01-27 11:53:44.315069 +0000][Dump ][AsyncSock ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Received a message of 8 bytes
[2021-01-27 11:53:44.315085 +0000][Debug ][XRootDTransport ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Authenticated with unix.
[2021-01-27 11:53:44.315113 +0000][Debug ][PostMaster ] [eos-mgm1.alice-af.wigner.hu:1094 #0] Stream 0 connected.
[2021-01-27 11:53:44.315129 +0000][Debug ][Utility ] Monitor library name not set. No monitoring
[2021-01-27 11:53:44.315198 +0000][Dump ][AsyncSock ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Wrote a message: kXR_stat (path: /eos/testarea/., flags: none) (0x1a72f60), 39 bytes
[2021-01-27 11:53:44.315211 +0000][Dump ][AsyncSock ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Successfully sent message: kXR_stat (path: /eos/testarea/., flags: none) (0x1a72f60).
[2021-01-27 11:53:44.315229 +0000][Dump ][XRootD ] [eos-mgm1.alice-af.wigner.hu:1094] Message kXR_stat (path: /eos/testarea/., flags: none) has been successfully sent.
[2021-01-27 11:53:44.315241 +0000][Debug ][ExDbgMsg ] [eos-mgm1.alice-af.wigner.hu:1094] Moving MsgHandler: 0x1a783a0 (message: kXR_stat (path: /eos/testarea/., flags: none) ) from out-queu to in-queue.
[2021-01-27 11:53:44.315272 +0000][Dump ][PostMaster ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] All messages consumed, disable uplink
[2021-01-27 11:53:44.315526 +0000][Dump ][XRootDTransport ] [msg: 0x80008c0] Expecting 29 bytes of message body
[2021-01-27 11:53:44.315540 +0000][Dump ][AsyncSock ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Received message header for 0x80008c0 size: 8
[2021-01-27 11:53:44.315563 +0000][Dump ][AsyncSock ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Received message 0x80008c0 of 37 bytes
[2021-01-27 11:53:44.315579 +0000][Dump ][PostMaster ] [eos-mgm1.alice-af.wigner.hu:1094 #0] Handling received message: 0x80008c0.
[2021-01-27 11:53:44.315658 +0000][Dump ][XRootD ] [eos-mgm1.alice-af.wigner.hu:1094] Got a kXR_ok response to request kXR_stat (path: /eos/testarea/., flags: none)
[2021-01-27 11:53:44.315710 +0000][Debug ][ExDbgMsg ] [eos-mgm1.alice-af.wigner.hu:1094] Calling MsgHandler: 0x1a783a0 (message: kXR_stat (path: /eos/testarea/., flags: none) ) with status: [SUCCESS] .
[2021-01-27 11:53:44.315731 +0000][Dump ][XRootD ] [eos-mgm1.alice-af.wigner.hu:1094] Parsing the response to kXR_stat (path: /eos/testarea/., flags: none) as StatInfo: 214748416767 0 51 1603730767
[2021-01-27 11:53:44.315786 +0000][Debug ][ExDbgMsg ] [eos-mgm1.alice-af.wigner.hu:1094] Destroying MsgHandler: 0x1a783a0.
[2021-01-27 11:53:44.315895 +0000][Dump ][App ] Processing source entry: root://eos-mgm1.alice-af.wigner.hu:1094//eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a, type xroot, target file: root://eos-mgm1.alice-af.wigner.hu:1094//eos/testarea/.
[2021-01-27 11:53:44.316081 +0000][Dump ][Utility ] Adding job with properties: 'checkSumMode' = 'none', 'checkSumPreset' = '', 'checkSumType' = '', 'chunkSize' = '8388608', 'coerce' = '0', 'delegate' = '0', 'dynamicSource' = '0', 'force' = '1', 'initTimeout' = '600', 'makeDir' = '0', 'parallelChunks' = '4', 'posc' = '0', 'source' = 'root://eos-mgm1.alice-af.wigner.hu:1094//eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a', 'target' = 'root://eos-mgm1.alice-af.wigner.hu:1094//eos/testarea/.', 'targetIsDir' = '1', 'thirdParty' = 'only', 'tpcTimeout' = '1800', 'xcp' = '0', 'xcpBlockSize' = '134217728', 'zipArchive' = '0'
[2021-01-27 11:53:44.316128 +0000][Debug ][Utility ] CopyProcess: 2 jobs to prepare
[2021-01-27 11:53:44.316173 +0000][Dump ][Utility ] URL: root://eos-mgm1.alice-af.wigner.hu:1094//eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a
[2021-01-27 11:53:44.316173 +0000][Dump ][Utility ] Protocol: root
[2021-01-27 11:53:44.316173 +0000][Dump ][Utility ] User Name:
[2021-01-27 11:53:44.316173 +0000][Dump ][Utility ] Password:
[2021-01-27 11:53:44.316173 +0000][Dump ][Utility ] Host Name: eos-mgm1.alice-af.wigner.hu
[2021-01-27 11:53:44.316173 +0000][Dump ][Utility ] Port: 1094
[2021-01-27 11:53:44.316173 +0000][Dump ][Utility ] Path: /eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a
[2021-01-27 11:53:44.316219 +0000][Dump ][Utility ] URL: root://eos-mgm1.alice-af.wigner.hu:1094//eos/testarea/.
[2021-01-27 11:53:44.316219 +0000][Dump ][Utility ] Protocol: root
[2021-01-27 11:53:44.316219 +0000][Dump ][Utility ] User Name:
[2021-01-27 11:53:44.316219 +0000][Dump ][Utility ] Password:
[2021-01-27 11:53:44.316219 +0000][Dump ][Utility ] Host Name: eos-mgm1.alice-af.wigner.hu
[2021-01-27 11:53:44.316219 +0000][Dump ][Utility ] Port: 1094
[2021-01-27 11:53:44.316219 +0000][Dump ][Utility ] Path: /eos/testarea/.
[2021-01-27 11:53:44.316298 +0000][Dump ][Utility ] URL: root://eos-mgm1.alice-af.wigner.hu:1094//eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a
[2021-01-27 11:53:44.316298 +0000][Dump ][Utility ] Protocol: root
[2021-01-27 11:53:44.316298 +0000][Dump ][Utility ] User Name:
[2021-01-27 11:53:44.316298 +0000][Dump ][Utility ] Password:
[2021-01-27 11:53:44.316298 +0000][Dump ][Utility ] Host Name: eos-mgm1.alice-af.wigner.hu
[2021-01-27 11:53:44.316298 +0000][Dump ][Utility ] Port: 1094
[2021-01-27 11:53:44.316298 +0000][Dump ][Utility ] Path: /eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a
[2021-01-27 11:53:44.316335 +0000][Dump ][Utility ] URL: root://eos-mgm1.alice-af.wigner.hu:1094//eos/testarea/./b90e6ad6-30b6-11eb-b4e7-3b3b0705303a
[2021-01-27 11:53:44.316335 +0000][Dump ][Utility ] Protocol: root
[2021-01-27 11:53:44.316335 +0000][Dump ][Utility ] User Name:
[2021-01-27 11:53:44.316335 +0000][Dump ][Utility ] Password:
[2021-01-27 11:53:44.316335 +0000][Dump ][Utility ] Host Name: eos-mgm1.alice-af.wigner.hu
[2021-01-27 11:53:44.316335 +0000][Dump ][Utility ] Port: 1094
[2021-01-27 11:53:44.316335 +0000][Dump ][Utility ] Path: /eos/testarea/./b90e6ad6-30b6-11eb-b4e7-3b3b0705303a
[2021-01-27 11:53:44.316360 +0000][Debug ][Utility ] Creating a third party fall back copy job, from root://eos-mgm1.alice-af.wigner.hu:1094//eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a to root://eos-mgm1.alice-af.wigner.hu:1094//eos/testarea/./b90e6ad6-30b6-11eb-b4e7-3b3b0705303a
[2021-01-27 11:53:44.316416 +0000][Dump ][Utility ] URL: root://eos-mgm1.alice-af.wigner.hu:1094//eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a
[2021-01-27 11:53:44.316416 +0000][Dump ][Utility ] Protocol: root
[2021-01-27 11:53:44.316416 +0000][Dump ][Utility ] User Name:
[2021-01-27 11:53:44.316416 +0000][Dump ][Utility ] Password:
[2021-01-27 11:53:44.316416 +0000][Dump ][Utility ] Host Name: eos-mgm1.alice-af.wigner.hu
[2021-01-27 11:53:44.316416 +0000][Dump ][Utility ] Port: 1094
[2021-01-27 11:53:44.316416 +0000][Dump ][Utility ] Path: /eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a
[2021-01-27 11:53:44.316454 +0000][Dump ][Utility ] URL: root://eos-mgm1.alice-af.wigner.hu:1094//eos/testarea/./b90e6ad6-30b6-11eb-b4e7-3b3b0705303a
[2021-01-27 11:53:44.316454 +0000][Dump ][Utility ] Protocol: root
[2021-01-27 11:53:44.316454 +0000][Dump ][Utility ] User Name:
[2021-01-27 11:53:44.316454 +0000][Dump ][Utility ] Password:
[2021-01-27 11:53:44.316454 +0000][Dump ][Utility ] Host Name: eos-mgm1.alice-af.wigner.hu
[2021-01-27 11:53:44.316454 +0000][Dump ][Utility ] Port: 1094
[2021-01-27 11:53:44.316454 +0000][Dump ][Utility ] Path: /eos/testarea/./b90e6ad6-30b6-11eb-b4e7-3b3b0705303a
[2021-01-27 11:53:44.316491 +0000][Debug ][Utility ] Creating a third party copy job, from root://eos-mgm1.alice-af.wigner.hu:1094//eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a to root://eos-mgm1.alice-af.wigner.hu:1094//eos/testarea/./b90e6ad6-30b6-11eb-b4e7-3b3b0705303a
[2021-01-27 11:53:44.316514 +0000][Debug ][Utility ] Check if third party copy between root://eos-mgm1.alice-af.wigner.hu:1094//eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a and root://eos-mgm1.alice-af.wigner.hu:1094//eos/testarea/./b90e6ad6-30b6-11eb-b4e7-3b3b0705303a is possible
[2021-01-27 11:53:44.316551 +0000][Info ][Utility ] We are NOT using delegation
[2021-01-27 11:53:44.316592 +0000][Debug ][Utility ] Trying to open root://eos-mgm1.alice-af.wigner.hu:1094//eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a?tpc.stage=placement for reading
[2021-01-27 11:53:44.316625 +0000][Dump ][Utility ] URL: root://eos-mgm1.alice-af.wigner.hu:1094//eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a?tpc.stage=placement
[2021-01-27 11:53:44.316625 +0000][Dump ][Utility ] Protocol: root
[2021-01-27 11:53:44.316625 +0000][Dump ][Utility ] User Name:
[2021-01-27 11:53:44.316625 +0000][Dump ][Utility ] Password:
[2021-01-27 11:53:44.316625 +0000][Dump ][Utility ] Host Name: eos-mgm1.alice-af.wigner.hu
[2021-01-27 11:53:44.316625 +0000][Dump ][Utility ] Port: 1094
[2021-01-27 11:53:44.316625 +0000][Dump ][Utility ] Path: /eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a
[2021-01-27 11:53:44.316701 +0000][Dump ][Utility ] URL: root://eos-mgm1.alice-af.wigner.hu:1094//eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a?tpc.stage=placement
[2021-01-27 11:53:44.316701 +0000][Dump ][Utility ] Protocol: root
[2021-01-27 11:53:44.316701 +0000][Dump ][Utility ] User Name:
[2021-01-27 11:53:44.316701 +0000][Dump ][Utility ] Password:
[2021-01-27 11:53:44.316701 +0000][Dump ][Utility ] Host Name: eos-mgm1.alice-af.wigner.hu
[2021-01-27 11:53:44.316701 +0000][Dump ][Utility ] Port: 1094
[2021-01-27 11:53:44.316701 +0000][Dump ][Utility ] Path: /eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a
[2021-01-27 11:53:44.316749 +0000][Dump ][Utility ] URL: root://eos-mgm1.alice-af.wigner.hu:1094//eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a?tpc.stage=placement
[2021-01-27 11:53:44.316749 +0000][Dump ][Utility ] Protocol: root
[2021-01-27 11:53:44.316749 +0000][Dump ][Utility ] User Name:
[2021-01-27 11:53:44.316749 +0000][Dump ][Utility ] Password:
[2021-01-27 11:53:44.316749 +0000][Dump ][Utility ] Host Name: eos-mgm1.alice-af.wigner.hu
[2021-01-27 11:53:44.316749 +0000][Dump ][Utility ] Port: 1094
[2021-01-27 11:53:44.316749 +0000][Dump ][Utility ] Path: /eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a
[2021-01-27 11:53:44.316851 +0000][Debug ][File ] [0x1a7a1d0@root://eos-mgm1.alice-af.wigner.hu:1094//eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a?tpc.stage=placement&xrdcl.requuid=2a2838e6-6ba0-44c3-8f66-a6d0cc0d6988] Sending an open command
[2021-01-27 11:53:44.316881 +0000][Dump ][XRootD ] [eos-mgm1.alice-af.wigner.hu:1094] Sending message kXR_open (file: /eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a?tpc.stage=placement, mode: 00, flags: kXR_open_read kXR_async kXR_retstat )
[2021-01-27 11:53:44.316901 +0000][Debug ][ExDbgMsg ] [eos-mgm1.alice-af.wigner.hu:1094] MsgHandler created: 0x1a7a6c0 (message: kXR_open (file: /eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a?tpc.stage=placement, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) ).
[2021-01-27 11:53:44.316918 +0000][Dump ][PostMaster ] [eos-mgm1.alice-af.wigner.hu:1094 #0] Sending message kXR_open (file: /eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a?tpc.stage=placement, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) (0x1a793d0) through substream 0 expecting answer at 0
[2021-01-27 11:53:44.317321 +0000][Dump ][AsyncSock ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Wrote a message: kXR_open (file: /eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a?tpc.stage=placement, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) (0x1a793d0), 105 bytes
[2021-01-27 11:53:44.317358 +0000][Dump ][AsyncSock ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Successfully sent message: kXR_open (file: /eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a?tpc.stage=placement, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) (0x1a793d0).
[2021-01-27 11:53:44.317382 +0000][Dump ][XRootD ] [eos-mgm1.alice-af.wigner.hu:1094] Message kXR_open (file: /eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a?tpc.stage=placement, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) has been successfully sent.
[2021-01-27 11:53:44.317396 +0000][Debug ][ExDbgMsg ] [eos-mgm1.alice-af.wigner.hu:1094] Moving MsgHandler: 0x1a7a6c0 (message: kXR_open (file: /eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a?tpc.stage=placement, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) ) from out-queu to in-queue.
[2021-01-27 11:53:44.317410 +0000][Dump ][PostMaster ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] All messages consumed, disable uplink
[2021-01-27 11:53:44.317844 +0000][Dump ][XRootDTransport ] [msg: 0x8000a40] Expecting 100 bytes of message body
[2021-01-27 11:53:44.317859 +0000][Dump ][AsyncSock ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Received message header for 0x8000a40 size: 8
[2021-01-27 11:53:44.317876 +0000][Dump ][AsyncSock ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Received message 0x8000a40 of 108 bytes
[2021-01-27 11:53:44.317888 +0000][Dump ][PostMaster ] [eos-mgm1.alice-af.wigner.hu:1094 #0] Handling received message: 0x8000a40.
[2021-01-27 11:53:44.318048 +0000][Dump ][XRootD ] [eos-mgm1.alice-af.wigner.hu:1094] Got a kXR_error response to request kXR_open (file: /eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a?tpc.stage=placement, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) [3010] Unable to open /eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a; Permission denied
[2021-01-27 11:53:44.318102 +0000][Debug ][XRootD ] [eos-mgm1.alice-af.wigner.hu:1094] Handling error while processing kXR_open (file: /eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a?tpc.stage=placement, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ): [ERROR] Error response: Permission denied.
[2021-01-27 11:53:44.318130 +0000][Debug ][ExDbgMsg ] [eos-mgm1.alice-af.wigner.hu:1094] Calling MsgHandler: 0x1a7a6c0 (message: kXR_open (file: /eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a?tpc.stage=placement, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) ) with status: [ERROR] Error response: Permission denied.
[2021-01-27 11:53:44.318216 +0000][Debug ][File ] [0x1a7a1d0@root://eos-mgm1.alice-af.wigner.hu:1094//eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a?tpc.stage=placement&xrdcl.requuid=2a2838e6-6ba0-44c3-8f66-a6d0cc0d6988] Open has returned with status [ERROR] Server responded with an error: [3010] Unable to open /eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a; Permission denied
[2021-01-27 11:53:44.318235 +0000][Debug ][File ] [0x1a7a1d0@root://eos-mgm1.alice-af.wigner.hu:1094//eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a?tpc.stage=placement&xrdcl.requuid=2a2838e6-6ba0-44c3-8f66-a6d0cc0d6988] Error while opening at eos-mgm1.alice-af.wigner.hu:1094: [ERROR] Server responded with an error: [3010] Unable to open /eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a; Permission denied
[2021-01-27 11:53:44.318263 +0000][Debug ][ExDbgMsg ] [eos-mgm1.alice-af.wigner.hu:1094] Destroying MsgHandler: 0x1a7a6c0.
[2021-01-27 11:53:44.318283 +0000][Info ][Utility ] Cannot open source file root://eos-mgm1.alice-af.wigner.hu:1094//eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a: [ERROR] Server responded with an error: [3010] Unable to open /eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a; Permission denied
[0B/0B][100%][==================================================][0B/s]
Run: [ERROR] Server responded with an error: [3010] Unable to open /eos/alice/grid/00/00208/b90e6ad6-30b6-11eb-b4e7-3b3b0705303a; Permission denied
[2021-01-27 11:53:44.318514 +0000][Debug ][JobMgr ] Stopping the job manager...
[2021-01-27 11:53:44.318527 +0000][Dump ][JobMgr ] Stopping worker #0...
[2021-01-27 11:53:44.318679 +0000][Dump ][JobMgr ] Worker #0 stopped
[2021-01-27 11:53:44.318696 +0000][Dump ][JobMgr ] Stopping worker #1...
[2021-01-27 11:53:44.318762 +0000][Dump ][JobMgr ] Worker #1 stopped
[2021-01-27 11:53:44.318778 +0000][Dump ][JobMgr ] Stopping worker #2...
[2021-01-27 11:53:44.318841 +0000][Dump ][JobMgr ] Worker #2 stopped
[2021-01-27 11:53:44.318858 +0000][Debug ][JobMgr ] Job manager stopped
[2021-01-27 11:53:44.318869 +0000][Debug ][TaskMgr ] Stopping the task manager...
[2021-01-27 11:53:44.318976 +0000][Debug ][TaskMgr ] Task manager stopped
[2021-01-27 11:53:44.318993 +0000][Debug ][Poller ] Stopping the poller...
[2021-01-27 11:53:44.319110 +0000][Debug ][TaskMgr ] Requesting unregistration of: "TickGeneratorTask for: eos-mgm1.alice-af.wigner.hu:1094"
[2021-01-27 11:53:44.319157 +0000][Debug ][AsyncSock ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Closing the socket
[2021-01-27 11:53:44.319199 +0000][Debug ][Poller ] <[::ffff:172.16.152.16]:32768><--><[::ffff:172.16.152.16]:1094> Removing socket from the poller
[2021-01-27 11:53:44.319258 +0000][Debug ][PostMaster ] [eos-mgm1.alice-af.wigner.hu:1094 #0] Destroying stream
[2021-01-27 11:53:44.319274 +0000][Debug ][AsyncSock ] [eos-mgm1.alice-af.wigner.hu:1094 #0.0] Closing the socket
Hi Gabor,
This will not work since you need the alice token to pass the authorization step. Do you have logs from the test that is performed by Alice? If not can you at least send me the MGM/FST logs from a recent failing transfer?
Thanks,
Elvin
Hi Elvin,
the /etc/grid-security/xrootd/TkAuthz.Authorization and /usr/lib64/libXrdAliceTokenAcc.so files are present on all nodes - what else might be necessary?
This is the xrdlog.mgm from around the test:
210127 15:22:27 13231 XrootdXeq: User authentication failed; Decryption key not found.
210127 15:22:28 13231 XrootdXeq: monalisa.28205:128@pcalimonitor.cern.ch pub IP46 login as monalisa
210127 15:22:28 time=1611760948.061351 func=IdMap level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94da1ce700 source=Mapping:1033 tident= sec=(null) uid=99 gid=99 name=- geo="" sec.prot=unix sec.name="monalisa" sec.host="pcalimonitor.cern.ch" sec.vorg="" sec.grps="alienmaster" sec.role="" sec.info="" sec.app="" sec.tident="monalisa.28205:128@pcalimonitor.cern.ch" vid.uid=99 vid.gid=99
210127 15:22:28 time=1611760948.061449 func=open level=INFO logid=7739abb6-60b3-11eb-9b84-00259074c8e8 unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94da1ce700 source=XrdMgmOfsFile:455 tident=monalisa.28205:128@pcalimonitor.cern.ch sec=unix uid=99 gid=99 name=monalisa geo="" op=write trunc=512 path=/eos/alice/grid/01/01510/771fd740-60b3-11eb-9cf6-0242ec98ab37 info=authz=<...>&oss.asize=10459447
210127 15:22:28 time=1611760948.063578 func=_mkdir level=INFO logid=xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94da1ce700 source=Mkdir:101 tident=<single-exec> sec=unix uid=99 gid=99 name=monalisa geo="" path=/eos/alice/grid/01/01510/
210127 15:22:28 time=1611760948.063710 func=_mkdir level=INFO logid=xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94da1ce700 source=Mkdir:138 tident=<single-exec> sec=unix uid=99 gid=99 name=monalisa geo="" path=/eos/alice/grid/01/ acl=0 r=0 w=0 wo=0 egroup=0 mutable=1
210127 15:22:28 time=1611760948.063835 func=BroadcastReleaseFromExternal level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94da1ce700 source=Caps:155 tident= sec=(null) uid=99 gid=99 name=- geo="" id=c9f mInodeCaps.count=0
210127 15:22:28 time=1611760948.063871 func=BroadcastReleaseFromExternal level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94da1ce700 source=Caps:155 tident= sec=(null) uid=99 gid=99 name=- geo="" id=1a mInodeCaps.count=0
210127 15:22:28 time=1611760948.063914 func=BroadcastRefreshFromExternal level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94da1ce700 source=Caps:202 tident= sec=(null) uid=99 gid=99 name=- geo="" id=1a pid=18
210127 15:22:28 time=1611760948.064061 func=open level=INFO logid=7739abb6-60b3-11eb-9b84-00259074c8e8 unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94da1ce700 source=XrdMgmOfsFile:945 tident=monalisa.28205:128@pcalimonitor.cern.ch sec=unix uid=99 gid=99 name=monalisa geo="" acl=0 r=0 w=0 wo=0 egroup=0 shared=0 mutable=1
210127 15:22:28 time=1611760948.065098 func=BroadcastReleaseFromExternal level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94da1ce700 source=Caps:155 tident= sec=(null) uid=99 gid=99 name=- geo="" id=c9f mInodeCaps.count=0
210127 15:22:28 time=1611760948.065132 func=BroadcastReleaseFromExternal level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94da1ce700 source=Caps:155 tident= sec=(null) uid=99 gid=99 name=- geo="" id=1a mInodeCaps.count=0
210127 15:22:28 time=1611760948.065157 func=BroadcastRefreshFromExternal level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94da1ce700 source=Caps:202 tident= sec=(null) uid=99 gid=99 name=- geo="" id=c9f pid=1a
210127 15:22:28 time=1611760948.065289 func=open level=INFO logid=7739abb6-60b3-11eb-9b84-00259074c8e8 unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94da1ce700 source=XrdMgmOfsFile:1411 tident=monalisa.28205:128@pcalimonitor.cern.ch sec=unix uid=99 gid=99 name=monalisa geo="" blocksize=4096 lid=100112
210127 15:22:28 time=1611760948.065356 func=BroadcastReleaseFromExternal level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94da1ce700 source=Caps:155 tident= sec=(null) uid=99 gid=99 name=- geo="" id=1b520000000 mInodeCaps.count=0
210127 15:22:28 time=1611760948.065380 func=BroadcastReleaseFromExternal level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94da1ce700 source=Caps:155 tident= sec=(null) uid=99 gid=99 name=- geo="" id=c9f mInodeCaps.count=0
210127 15:22:28 time=1611760948.065404 func=BroadcastReleaseFromExternal level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94da1ce700 source=Caps:155 tident= sec=(null) uid=99 gid=99 name=- geo="" id=1a mInodeCaps.count=0
210127 15:22:28 time=1611760948.065427 func=BroadcastRefreshFromExternal level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94da1ce700 source=Caps:202 tident= sec=(null) uid=99 gid=99 name=- geo="" id=c9f pid=1a
210127 15:22:28 time=1611760948.065493 func=CheckWriteQuota level=INFO logid=c0bb1ae2-60b1-11eb-b1f9-00259074c8e8 unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94da1ce700 source=Quota:905 tident=<service> sec= uid=0 gid=0 name= geo="" uid=99 gid=99 size=20918894 quota=0
210127 15:22:28 time=1611760948.065514 func=CheckWriteQuota level=INFO logid=c0bb1ae2-60b1-11eb-b1f9-00259074c8e8 unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94da1ce700 source=Quota:998 tident=<service> sec= uid=0 gid=0 name= geo="" userquota=0 groupquota=1 hasuserquota=0 hasgroupquota=1 userinodequota=0 uservolumequota=0 projectquota=0 hasprojectquota=1
210127 15:22:28 time=1611760948.066194 func=open level=INFO logid=7739abb6-60b3-11eb-9b84-00259074c8e8 unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94da1ce700 source=XrdMgmOfsFile:2749 tident=monalisa.28205:128@pcalimonitor.cern.ch sec=unix uid=99 gid=99 name=monalisa geo="" op=write path=/eos/alice/grid/01/01510/771fd740-60b3-11eb-9cf6-0242ec98ab37 info=authz=<...>&oss.asize=10459447 target[0]=(eos-fst07.alice-af.wigner.hu,161) target[1]=(eos-fst04.alice-af.wigner.hu,65) redirection=eos-fst07.alice-af.wigner.hu?&cap.sym=<...>&cap.msg=<...>&mgm.logid=7739abb6-60b3-11eb-9b84-00259074c8e8&mgm.replicaindex=0&mgm.replicahead=0&mgm.id=00001b52:1095
210127 15:22:28 time=1611760948.066233 func=open level=INFO logid=7739abb6-60b3-11eb-9b84-00259074c8e8 unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94da1ce700 source=XrdMgmOfsFile:2757 tident=monalisa.28205:128@pcalimonitor.cern.ch sec=unix uid=99 gid=99 name=monalisa geo="" info="redirection" hostport=eos-fst07.alice-af.wigner.hu?&cap.sym=<...>&cap.msg=<...>&mgm.logid=7739abb6-60b3-11eb-9b84-00259074c8e8&mgm.replicaindex=0&mgm.replicahead=0&mgm.id=00001b52:1095
210127 15:22:28 time=1611760948.689857 func=log_info level=INFO logid=7739abb6-60b3-11eb-9b84-00259074c8e8 unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d6dee700 source=CommitHelper:207 tident=daemon.2637:127@eos-fst07 sec=sss uid=2 gid=2 name=daemon geo="" subcmd=commit path=/eos/alice/grid/01/01510/771fd740-60b3-11eb-9cf6-0242ec98ab37 size=10459447 fxid=00001b52 fsid=161 dropfsid= checksum=ee06f584 mtime=1611760948 mtime.nsec=689325000 oc-chunk=0 oc-n=0 oc-max=0 oc-uuid=
210127 15:22:28 time=1611760948.689993 func=BroadcastReleaseFromExternal level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d6dee700 source=Caps:155 tident= sec=(null) uid=99 gid=99 name=- geo="" id=c9f mInodeCaps.count=0
210127 15:22:28 time=1611760948.690021 func=BroadcastRefreshFromExternal level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d6dee700 source=Caps:202 tident= sec=(null) uid=99 gid=99 name=- geo="" id=c9f pid=1a
210127 15:22:28 time=1611760948.690046 func=BroadcastRefreshFromExternal level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d6dee700 source=Caps:202 tident= sec=(null) uid=99 gid=99 name=- geo="" id=1b520000000 pid=c9f
210127 15:22:28 time=1611760948.690071 func=Commit level=INFO logid=7739abb6-60b3-11eb-9b84-00259074c8e8 unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d6dee700 source=Commit:268 tident=daemon.2637:127@eos-fst07 sec=sss uid=2 gid=2 name=daemon geo="" commitsize=1 n1=771fd740-60b3-11eb-9cf6-0242ec98ab37 n2=771fd740-60b3-11eb-9cf6-0242ec98ab37 occhunk=0 ocdone=0
210127 15:22:28 time=1611760948.691981 func=log_info level=INFO logid=7739abb6-60b3-11eb-9b84-00259074c8e8 unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d7de6700 source=CommitHelper:207 tident=daemon.2681:123@eos-fst04 sec=sss uid=2 gid=2 name=daemon geo="" subcmd=commit path=/eos/alice/grid/01/01510/771fd740-60b3-11eb-9cf6-0242ec98ab37 size=10459447 fxid=00001b52 fsid=65 dropfsid= checksum=ee06f584 mtime=1611760948 mtime.nsec=687883000 oc-chunk=0 oc-n=0 oc-max=0 oc-uuid=
210127 15:22:28 time=1611760948.692085 func=Commit level=INFO logid=7739abb6-60b3-11eb-9b84-00259074c8e8 unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d7de6700 source=Commit:268 tident=daemon.2681:123@eos-fst04 sec=sss uid=2 gid=2 name=daemon geo="" commitsize=0 n1=771fd740-60b3-11eb-9cf6-0242ec98ab37 n2=771fd740-60b3-11eb-9cf6-0242ec98ab37 occhunk=0 ocdone=0
210127 15:22:28 13231 XrootdXeq: monalisa.28205:128@pcalimonitor.cern.ch disc 0:00:01
210127 15:22:28 12910 XrootdXeq: User authentication failed; Decryption key not found.
210127 15:22:28 12910 XrootdXeq: monalisa.32598:129@pcalimonitor.cern.ch pub IP46 login as monalisa
210127 15:22:28 12910 XrootdXeq: monalisa.32598:129@pcalimonitor.cern.ch disc 0:00:00
210127 15:22:28 13256 XrootdXeq: User authentication failed; Decryption key not found.
210127 15:22:28 13256 XrootdXeq: monalisa.33386:128@pcalimonitor.cern.ch pub IP46 login as monalisa
210127 15:22:29 time=1611760949.010489 func=IdMap level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d5df6700 source=Mapping:1033 tident= sec=(null) uid=99 gid=99 name=- geo="" sec.prot=unix sec.name="monalisa" sec.host="pcalimonitor.cern.ch" sec.vorg="" sec.grps="alienmaster" sec.role="" sec.info="" sec.app="" sec.tident="monalisa.33386:128@pcalimonitor.cern.ch" vid.uid=99 vid.gid=99
210127 15:22:29 time=1611760949.010584 func=open level=INFO logid=77ca7e66-60b3-11eb-9356-00259074c8e8 unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d5df6700 source=XrdMgmOfsFile:457 tident=monalisa.33386:128@pcalimonitor.cern.ch sec=unix uid=99 gid=99 name=monalisa geo="" op=read path=/eos/alice/grid/01/01510/771fd740-60b3-11eb-9cf6-0242ec98ab37 info=authz=<...>
210127 15:22:29 time=1611760949.011795 func=open level=INFO logid=77ca7e66-60b3-11eb-9356-00259074c8e8 unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d5df6700 source=XrdMgmOfsFile:945 tident=monalisa.33386:128@pcalimonitor.cern.ch sec=unix uid=99 gid=99 name=monalisa geo="" acl=0 r=0 w=0 wo=0 egroup=0 shared=0 mutable=1
210127 15:22:29 time=1611760949.012701 func=open level=INFO logid=77ca7e66-60b3-11eb-9356-00259074c8e8 unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d5df6700 source=XrdMgmOfsFile:2753 tident=monalisa.33386:128@pcalimonitor.cern.ch sec=unix uid=99 gid=99 name=monalisa geo="" op=read path=/eos/alice/grid/01/01510/771fd740-60b3-11eb-9cf6-0242ec98ab37 info=authz=<...> target[0]=(eos-fst07.alice-af.wigner.hu,161) target[1]=(eos-fst04.alice-af.wigner.hu,65) redirection=eos-fst04.alice-af.wigner.hu?&cap.sym=<...>&cap.msg=<...>&mgm.logid=77ca7e66-60b3-11eb-9356-00259074c8e8&mgm.blockchecksum=ignore&mgm.replicaindex=1&mgm.replicahead=1&mgm.id=00001b52&mgm.mtime=1611760948:1095
210127 15:22:29 time=1611760949.012739 func=open level=INFO logid=77ca7e66-60b3-11eb-9356-00259074c8e8 unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d5df6700 source=XrdMgmOfsFile:2757 tident=monalisa.33386:128@pcalimonitor.cern.ch sec=unix uid=99 gid=99 name=monalisa geo="" info="redirection" hostport=eos-fst04.alice-af.wigner.hu?&cap.sym=<...>&cap.msg=<...>&mgm.logid=77ca7e66-60b3-11eb-9356-00259074c8e8&mgm.blockchecksum=ignore&mgm.replicaindex=1&mgm.replicahead=1&mgm.id=00001b52&mgm.mtime=1611760948:1095
210127 15:22:29 13256 XrootdXeq: monalisa.33386:128@pcalimonitor.cern.ch disc 0:00:01
210127 15:22:29 13253 XrootdXeq: User authentication failed; Decryption key not found.
210127 15:22:29 13253 XrootdXeq: monalisa.36277:129@pcalimonitor.cern.ch pub IP46 login as monalisa
210127 15:22:29 time=1611760949.644911 func=IdMap level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d8dde700 source=Mapping:1033 tident= sec=(null) uid=99 gid=99 name=- geo="" sec.prot=unix sec.name="monalisa" sec.host="pcalimonitor.cern.ch" sec.vorg="" sec.grps="alienmaster" sec.role="" sec.info="" sec.app="" sec.tident="monalisa.36277:129@pcalimonitor.cern.ch" vid.uid=99 vid.gid=99
210127 15:22:29 time=1611760949.645025 func=_rem level=INFO logid=xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d8dde700 source=Rm:105 tident=<single-exec> sec=unix uid=99 gid=99 name=monalisa geo="" path=/eos/alice/grid/01/01510/771fd740-60b3-11eb-9cf6-0242ec98ab37 vid.uid=99 vid.gid=99
210127 15:22:29 time=1611760949.645384 func=_rem level=INFO logid=xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d8dde700 source=Rm:165 tident=<single-exec> sec=unix uid=99 gid=99 name=monalisa geo="" acl= mutable=1
210127 15:22:29 time=1611760949.645420 func=_rem level=INFO logid=xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d8dde700 source=Rm:256 tident=<single-exec> sec=unix uid=99 gid=99 name=monalisa geo="" got quota node=140276605573120
210127 15:22:29 time=1611760949.645456 func=_rem level=INFO logid=xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d8dde700 source=Rm:275 tident=<single-exec> sec=unix uid=99 gid=99 name=monalisa geo="" unlinking from view /eos/alice/grid/01/01510/771fd740-60b3-11eb-9cf6-0242ec98ab37
210127 15:22:29 time=1611760949.645487 func=_rem level=INFO logid=xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d8dde700 source=Rm:284 tident=<single-exec> sec=unix uid=99 gid=99 name=monalisa geo="" msg="no workflow defined for delete"
210127 15:22:29 time=1611760949.645581 func=BroadcastReleaseFromExternal level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d8dde700 source=Caps:155 tident= sec=(null) uid=99 gid=99 name=- geo="" id=c9f mInodeCaps.count=0
210127 15:22:29 time=1611760949.645618 func=BroadcastDeletionFromExternal level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d8dde700 source=Caps:314 tident= sec=(null) uid=99 gid=99 name=- geo="" id=c9f name=771fd740-60b3-11eb-9cf6-0242ec98ab37
210127 15:22:29 time=1611760949.645660 func=BroadcastRefreshFromExternal level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d8dde700 source=Caps:202 tident= sec=(null) uid=99 gid=99 name=- geo="" id=c9f pid=1a
210127 15:22:29 time=1611760949.645700 func=PurgeVersion level=INFO logid=xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d8dde700 source=Version:170 tident=<single-exec> sec= uid=0 gid=0 name= geo="" version-dir=/eos/alice/grid/01/01510/.sys.v#.771fd740-60b3-11eb-9cf6-0242ec98ab37/ max-versions=0
210127 15:22:29 time=1611760949.645869 func=PurgeVersion level=INFO logid=xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d8dde700 source=Version:199 tident=<single-exec> sec= uid=0 gid=0 name= geo="" listrc=-1 max-version=0
210127 15:22:29 time=1611760949.645904 func=_rem level=INFO logid=xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d8dde700 source=Rm:429 tident=<single-exec> sec=unix uid=99 gid=99 name=monalisa geo="" msg="deleted" can-recycle=0 path=/eos/alice/grid/01/01510/771fd740-60b3-11eb-9cf6-0242ec98ab37 owner.uid=99 owner.gid=99 vid.uid=99 vid.gid=99
210127 15:22:29 13253 XrootdXeq: monalisa.36277:129@pcalimonitor.cern.ch disc 0:00:00
210127 15:22:29 13192 XrootdXeq: User authentication failed; Decryption key not found.
210127 15:22:29 13192 XrootdXeq: monalisa.36999:128@pcalimonitor.cern.ch pub IP46 login as monalisa
210127 15:22:29 time=1611760949.805238 func=IdMap level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94db58e700 source=Mapping:1033 tident= sec=(null) uid=99 gid=99 name=- geo="" sec.prot=unix sec.name="monalisa" sec.host="pcalimonitor.cern.ch" sec.vorg="" sec.grps="alienmaster" sec.role="" sec.info="" sec.app="" sec.tident="monalisa.36999:128@pcalimonitor.cern.ch" vid.uid=99 vid.gid=99
210127 15:22:29 time=1611760949.805335 func=_rem level=INFO logid=xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94db58e700 source=Rm:105 tident=<single-exec> sec=unix uid=99 gid=99 name=monalisa geo="" path=/eos/alice/grid/04/36435/05422528-a162-11e8-b5f9-a310691b2def vid.uid=99 vid.gid=99
210127 15:22:29 time=1611760949.805443 func=Emsg level=ERROR logid=xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94db58e700 source=XrdMgmOfs:1171 tident=<single-exec> sec= uid=0 gid=0 name= geo="" Unable to remove /eos/alice/grid/04/36435/05422528-a162-11e8-b5f9-a310691b2def; No such file or directory
210127 15:22:29 13192 XrootdXeq: monalisa.36999:128@pcalimonitor.cern.ch disc 0:00:00
210127 15:22:29 13308 XrootdXeq: User authentication failed; Decryption key not found.
210127 15:22:29 13308 XrootdXeq: monalisa.37670:129@pcalimonitor.cern.ch pub IP46 login as monalisa
210127 15:22:30 time=1611760950.018325 func=IdMap level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d4dee700 source=Mapping:1033 tident= sec=(null) uid=99 gid=99 name=- geo="" sec.prot=unix sec.name="monalisa" sec.host="pcalimonitor.cern.ch" sec.vorg="" sec.grps="alienmaster" sec.role="" sec.info="" sec.app="transfer-3rd" sec.tident="monalisa.37670:129@pcalimonitor.cern.ch" vid.uid=99 vid.gid=99
210127 15:22:30 time=1611760950.018414 func=open level=INFO logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d4dee700 source=XrdMgmOfsFile:455 tident=monalisa.37670:129@pcalimonitor.cern.ch sec=unix uid=99 gid=99 name=monalisa geo="" op=write trunc=512 path=/eos/alice/grid/04/36435/05422528-a162-11e8-b5f9-a310691b2def info=authz=<...>&eos.app=transfer-3rd&oss.asize=249&tpc.dlg=eosalice.cern.ch:1094&tpc.dlgon=0&tpc.key=0048785a9b5a932660118536&tpc.lfn=/04/36435/05422528-a162-11e8-b5f9-a310691b2def&tpc.spr=root&tpc.src=st-096-dd907c42.cern.ch:1095&tpc.stage=copy&tpc.str=1&tpc.tpr=root
210127 15:22:30 time=1611760950.018536 func=open level=INFO logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d4dee700 source=XrdMgmOfsFile:566 tident=monalisa.37670:129@pcalimonitor.cern.ch sec=unix uid=99 gid=99 name=monalisa geo="" msg="rewrote symlinks" sym-path=/eos/alice/grid/04/36435/05422528-a162-11e8-b5f9-a310691b2def realpath=/eos/alice/grid/04/36435/05422528-a162-11e8-b5f9-a310691b2def
210127 15:22:30 time=1611760950.019355 func=open level=INFO logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d4dee700 source=XrdMgmOfsFile:945 tident=monalisa.37670:129@pcalimonitor.cern.ch sec=unix uid=99 gid=99 name=monalisa geo="" acl=0 r=0 w=0 wo=0 egroup=0 shared=0 mutable=1
210127 15:22:30 time=1611760950.019477 func=BroadcastReleaseFromExternal level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d4dee700 source=Caps:155 tident= sec=(null) uid=99 gid=99 name=- geo="" id=34 mInodeCaps.count=0
210127 15:22:30 time=1611760950.019502 func=BroadcastReleaseFromExternal level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d4dee700 source=Caps:155 tident= sec=(null) uid=99 gid=99 name=- geo="" id=1d mInodeCaps.count=0
210127 15:22:30 time=1611760950.019529 func=BroadcastRefreshFromExternal level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d4dee700 source=Caps:202 tident= sec=(null) uid=99 gid=99 name=- geo="" id=34 pid=1d
210127 15:22:30 time=1611760950.019625 func=open level=INFO logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d4dee700 source=XrdMgmOfsFile:1411 tident=monalisa.37670:129@pcalimonitor.cern.ch sec=unix uid=99 gid=99 name=monalisa geo="" blocksize=4096 lid=100112
210127 15:22:30 time=1611760950.019677 func=BroadcastReleaseFromExternal level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d4dee700 source=Caps:155 tident= sec=(null) uid=99 gid=99 name=- geo="" id=1b530000000 mInodeCaps.count=0
210127 15:22:30 time=1611760950.019701 func=BroadcastReleaseFromExternal level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d4dee700 source=Caps:155 tident= sec=(null) uid=99 gid=99 name=- geo="" id=34 mInodeCaps.count=0
210127 15:22:30 time=1611760950.019732 func=BroadcastReleaseFromExternal level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d4dee700 source=Caps:155 tident= sec=(null) uid=99 gid=99 name=- geo="" id=1d mInodeCaps.count=0
210127 15:22:30 time=1611760950.019756 func=BroadcastRefreshFromExternal level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d4dee700 source=Caps:202 tident= sec=(null) uid=99 gid=99 name=- geo="" id=34 pid=1d
210127 15:22:30 time=1611760950.019808 func=CheckWriteQuota level=INFO logid=c0bb1ae2-60b1-11eb-b1f9-00259074c8e8 unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d4dee700 source=Quota:905 tident=<service> sec= uid=0 gid=0 name= geo="" uid=99 gid=99 size=498 quota=0
210127 15:22:30 time=1611760950.019828 func=CheckWriteQuota level=INFO logid=c0bb1ae2-60b1-11eb-b1f9-00259074c8e8 unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d4dee700 source=Quota:998 tident=<service> sec= uid=0 gid=0 name= geo="" userquota=0 groupquota=1 hasuserquota=0 hasgroupquota=1 userinodequota=0 uservolumequota=0 projectquota=0 hasprojectquota=1
210127 15:22:30 time=1611760950.020401 func=open level=INFO logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d4dee700 source=XrdMgmOfsFile:2749 tident=monalisa.37670:129@pcalimonitor.cern.ch sec=unix uid=99 gid=99 name=monalisa geo="" op=write path=/eos/alice/grid/04/36435/05422528-a162-11e8-b5f9-a310691b2def info=authz=<...>&eos.app=transfer-3rd&oss.asize=249&tpc.dlg=eosalice.cern.ch:1094&tpc.dlgon=0&tpc.key=0048785a9b5a932660118536&tpc.lfn=/04/36435/05422528-a162-11e8-b5f9-a310691b2def&tpc.spr=root&tpc.src=st-096-dd907c42.cern.ch:1095&tpc.stage=copy&tpc.str=1&tpc.tpr=root target[0]=(eos-fst06.alice-af.wigner.hu,138) target[1]=(eos-fst03.alice-af.wigner.hu,90) redirection=eos-fst06.alice-af.wigner.hu?&cap.sym=<...>&cap.msg=<...>&mgm.logid=7864482a-60b3-11eb-be60-00259074c8e8&mgm.replicaindex=0&mgm.replicahead=0&mgm.id=00001b53:1095
210127 15:22:30 time=1611760950.020433 func=open level=INFO logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d4dee700 source=XrdMgmOfsFile:2757 tident=monalisa.37670:129@pcalimonitor.cern.ch sec=unix uid=99 gid=99 name=monalisa geo="" info="redirection" hostport=eos-fst06.alice-af.wigner.hu?&cap.sym=<...>&cap.msg=<...>&mgm.logid=7864482a-60b3-11eb-be60-00259074c8e8&mgm.replicaindex=0&mgm.replicahead=0&mgm.id=00001b53:1095
210127 15:22:33 time=1611760953.454263 func=Recycler level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f949bba6700 source=Recycle:99 tident= sec=(null) uid=99 gid=99 name=- geo="" snooze-time=30
210127 15:22:36 time=1611760956.500127 func=Drop level=INFO logid=xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f951cefe700 source=Drop:55 tident=daemon.2640:125@eos-fst06 sec=sss uid=2 gid=2 name=daemon geo="" drop request for &mgm.pcmd=drop&mgm.fsid=138&mgm.fid=00001b53&mgm.dropall=1
210127 15:22:36 time=1611760956.500247 func=BroadcastReleaseFromExternal level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f951cefe700 source=Caps:155 tident= sec=(null) uid=99 gid=99 name=- geo="" id=34 mInodeCaps.count=0
210127 15:22:36 time=1611760956.500280 func=BroadcastRefreshFromExternal level=INFO logid=static.............................. unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f951cefe700 source=Caps:202 tident= sec=(null) uid=99 gid=99 name=- geo="" id=34 pid=1d
210127 15:22:36 time=1611760956.502314 func=Drop level=INFO logid=xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d5df6700 source=Drop:55 tident=daemon.2741:122@eos-fst03 sec=sss uid=2 gid=2 name=daemon geo="" drop request for &mgm.pcmd=drop&mgm.fsid=90&mgm.fid=00001b53
210127 15:22:36 time=1611760956.502396 func=Drop level=WARN logid=xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx unit=mgm@eos-mgm1.alice-af.wigner.hu:1094 tid=00007f94d5df6700 source=Drop:69 tident=daemon.2741:122@eos-fst03 sec=sss uid=2 gid=2 name=daemon geo="" no meta record exists anymore for fxid=00001b53
210127 15:22:36 13253 XrootdXeq: monalisa.37670:129@pcalimonitor.cern.ch disc 0:00:07
(I post the output from the FST in the next post due to the character limit)
Additionally, I don’t know if it is related to this issue or not, the ALICE monitoring services can see only 65 TB (~the size of one single FST node) instead the full installed size. I also don’t understand why, since the traffic is visible on all nodes: http://alimonitor.cern.ch/?3395
Thanks for your time and help!
Gabor
And this is from the FST:
210127 15:22:30 2648 XrootdXeq: monalisa.37670:34@pcalimonitor.cern.ch pub IP46 login as monalisa
210127 15:22:30 time=1611760950.140573 func=open level=INFO logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f3503dfd700 source=XrdFstOfsFile:119 tident=monalisa.37670:34@pcalimonitor.cern.ch sec=unix uid=0 gid=0 name=monalisa geo="" path=/04/36435/05422528-a162-11e8-b5f9-a310691b2def info=authz=<...>&cap.msg=<...>&cap.sym=<...>&eos.app=transfer-3rd&mgm.id=00001b53&mgm.logid=7864482a-60b3-11eb-be60-00259074c8e8&mgm.replicahead=0&mgm.replicaindex=0&oss.asize=249&tpc.dlg=eosalice.cern.ch:1094&tpc.dlgon=0&tpc.key=0048785a9b5a932660118536&tpc.lfn=/04/36435/05422528-a162-11e8-b5f9-a310691b2def&tpc.spr=root&tpc.src=st-096-dd907c42.cern.ch:1095&tpc.stage=copy&tpc.str=1&tpc.tpr=root open_mode=200
210127 15:22:30 time=1611760950.171051 func=ProcessTpcOpaque level=INFO logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f3503dfd700 source=XrdFstOfsFile:2511 tident=monalisa.37670:34@pcalimonitor.cern.ch sec=unix uid=0 gid=0 name=monalisa geo="" msg="tpc dst session" key=0048785a9b5a932660118536, org=monalisa.37670@pcalimonitor.cern.ch, src=st-096-dd907c42.cern.ch:1095 path=/04/36435/05422528-a162-11e8-b5f9-a310691b2def lfn=/04/36435/05422528-a162-11e8-b5f9-a310691b2def expires=1611761070
210127 15:22:30 time=1611760950.171331 func=ProcessCapOpaque level=INFO logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f3503dfd700 source=XrdFstOfsFile:2223 tident=monalisa.37670:34@pcalimonitor.cern.ch sec=(null) uid=99 gid=99 name=(null) geo="" capability=&mgm.access=create&mgm.ruid=99&mgm.rgid=99&mgm.uid=99&mgm.gid=99&mgm.path=/eos/alice/grid/04/36435/05422528-a162-11e8-b5f9-a310691b2def&mgm.manager=eos-mgm1.alice-af.wigner.hu:1094&mgm.fid=00001b53&mgm.cid=52&mgm.sec=unix|monalisa|pcalimonitor.cern.ch||alienmaster|||transfer-3rd&mgm.lid=1048850&mgm.bookingsize=249&mgm.targetsize=249&mgm.fsid=138&mgm.url0=root://eos-fst06.alice-af.wigner.hu:1095//&mgm.fsid0=138&mgm.url1=root://eos-fst03.alice-af.wigner.hu:1095//&mgm.fsid1=90&cap.valid=1611764550
210127 15:22:30 time=1611760950.171397 func=open level=INFO logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f3503dfd700 source=XrdFstOfsFile:197 tident=monalisa.37670:34@pcalimonitor.cern.ch sec=(null) uid=99 gid=99 name=nobody geo="" ns_path=/04/36435/05422528-a162-11e8-b5f9-a310691b2def fst_path=/data3/00000000/00001b53
210127 15:22:30 time=1611760950.192880 func=open level=INFO logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f3503dfd700 source=XrdFstOfsFile:452 tident=monalisa.37670:34@pcalimonitor.cern.ch sec=(null) uid=99 gid=99 name=nobody geo="" fst_path=/data3/00000000/00001b53 open-mode=300 create-mode=4180 layout-name=replica
210127 15:22:30 time=1611760950.192909 func=Open level=INFO logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f3503dfd700 source=ReplicaParLayout:104 tident=monalisa.37670:34@pcalimonitor.cern.ch sec=unix uid=0 gid=0 name=monalisa geo="" replica_head=0, replica_index=0
210127 15:22:30 time=1611760950.192992 func=fileOpen level=INFO logid=787ef17a-60b3-11eb-90ed-002590704734 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f3503dfd700 source=LocalIo:70 tident=<service> sec= uid=0 gid=0 name= geo="" flags=300, path=/data3/00000000/00001b53
210127 15:22:30 time=1611760950.280172 func=stat level=INFO logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f3503dfd700 source=XrdFstOfsFile:912 tident=monalisa.37670:34@pcalimonitor.cern.ch sec= uid=99 gid=99 name=nobody geo="" path=/04/36435/05422528-a162-11e8-b5f9-a310691b2def fxid=00001b53 size=249 mtime=1611760950.130164938
210127 15:22:30 time=1611760950.328339 func=sync level=INFO logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f3503dfd700 source=XrdFstOfsFile:930 tident=monalisa.37670:34@pcalimonitor.cern.ch sec= uid=99 gid=99 name=nobody geo="" msg="tpc enabled -> 1st sync"
210127 15:22:30 time=1611760950.328676 func=DoTpcTransfer level=INFO logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f34e61f0700 source=XrdFstOfsFile:3124 tident=monalisa.37670:34@pcalimonitor.cern.ch sec= uid=99 gid=99 name=nobody geo="" msg="tpc now running - 1st sync"
210127 15:22:30 time=1611760950.329078 func=DoTpcTransfer level=INFO logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f34e61f0700 source=XrdFstOfsFile:3155 tident=monalisa.37670:34@pcalimonitor.cern.ch sec= uid=99 gid=99 name=nobody geo="" sync-url=root://st-096-dd907c42.cern.ch:1095//04/36435/05422528-a162-11e8-b5f9-a310691b2def?fst.readahead=true sync-cgi=tpc.key=0048785a9b5a932660118536&tpc.org=monalisa.37670@pcalimonitor.cern.ch
210127 15:22:30 time=1611760950.352665 func=sync level=INFO logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f3503dfd700 source=XrdFstOfsFile:952 tident=monalisa.37670:34@pcalimonitor.cern.ch sec= uid=99 gid=99 name=nobody geo="" msg="tpc running -> 2nd sync"
210127 15:22:31 time=1611760951.353503 func=stat level=INFO logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f3503dfd700 source=XrdFstOfsFile:912 tident=monalisa.37670:34@pcalimonitor.cern.ch sec= uid=99 gid=99 name=nobody geo="" path=/04/36435/05422528-a162-11e8-b5f9-a310691b2def fxid=00001b53 size=249 mtime=1611760950.130164938
210127 15:22:32 time=1611760952.377066 func=stat level=INFO logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f3503dfd700 source=XrdFstOfsFile:912 tident=monalisa.37670:34@pcalimonitor.cern.ch sec= uid=99 gid=99 name=nobody geo="" path=/04/36435/05422528-a162-11e8-b5f9-a310691b2def fxid=00001b53 size=249 mtime=1611760950.130164938
210127 15:22:33 time=1611760953.401002 func=stat level=INFO logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f3503dfd700 source=XrdFstOfsFile:912 tident=monalisa.37670:34@pcalimonitor.cern.ch sec= uid=99 gid=99 name=nobody geo="" path=/04/36435/05422528-a162-11e8-b5f9-a310691b2def fxid=00001b53 size=249 mtime=1611760950.130164938
210127 15:22:34 time=1611760954.424420 func=stat level=INFO logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f3503dfd700 source=XrdFstOfsFile:912 tident=monalisa.37670:34@pcalimonitor.cern.ch sec= uid=99 gid=99 name=nobody geo="" path=/04/36435/05422528-a162-11e8-b5f9-a310691b2def fxid=00001b53 size=249 mtime=1611760950.130164938
210127 15:22:35 time=1611760955.447783 func=stat level=INFO logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f3503dfd700 source=XrdFstOfsFile:912 tident=monalisa.37670:34@pcalimonitor.cern.ch sec= uid=99 gid=99 name=nobody geo="" path=/04/36435/05422528-a162-11e8-b5f9-a310691b2def fxid=00001b53 size=249 mtime=1611760950.130164938
210127 15:22:36 time=1611760956.223378 func=fileOpen level=ERROR logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f34e61f0700 source=XrdIo:233 tident=<service> sec= uid=0 gid=0 name= geo="" error= "open failed url=root://st-096-dd907c42.cern.ch:1095//04/36435/05422528-a162-11e8-b5f9-a310691b2def?fst.readahead=true&fst.valid=1611761009&tpc.key=0048785a9b5a932660118536&tpc.org=monalisa.37670@pcalimonitor.cern.ch, errno=0, errc=103, msg=[FATAL] Socket timeout"
210127 15:22:36 time=1611760956.223449 func=fileOpen level=WARN logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f34e61f0700 source=XrdIo:236 tident=<service> sec= uid=0 gid=0 name= geo="" error encountered despite errno=0; setting errno=22
210127 15:22:36 time=1611760956.223467 func=DoTpcTransfer level=ERROR logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f34e61f0700 source=XrdFstOfsFile:3159 tident=monalisa.37670:34@pcalimonitor.cern.ch sec= uid=99 gid=99 name=nobody geo="" msg="TPC open failed for url=root://st-096-dd907c42.cern.ch:1095//04/36435/05422528-a162-11e8-b5f9-a310691b2def?fst.readahead=true cgi=tpc.key=0048785a9b5a932660118536&tpc.org=monalisa.37670@pcalimonitor.cern.ch"
210127 15:22:36 time=1611760956.472017 func=stat level=INFO logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f3503dfd700 source=XrdFstOfsFile:912 tident=monalisa.37670:34@pcalimonitor.cern.ch sec= uid=99 gid=99 name=nobody geo="" path=/04/36435/05422528-a162-11e8-b5f9-a310691b2def fxid=00001b53 size=249 mtime=1611760950.130164938
210127 15:22:36 time=1611760956.496965 func=_close level=INFO logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f3503dfd700 source=XrdFstOfsFile:1092 tident=monalisa.37670:34@pcalimonitor.cern.ch sec= uid=99 gid=99 name=nobody geo="" msg="remove tpc key" key=0048785a9b5a932660118536
210127 15:22:36 time=1611760956.497051 func=_close level=INFO logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f3503dfd700 source=XrdFstOfsFile:1135 tident=monalisa.37670:34@pcalimonitor.cern.ch sec= uid=99 gid=99 name=nobody geo="" viaDelete=0 writeDelete=0
210127 15:22:36 time=1611760956.497102 func=VerifyChecksum level=INFO logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f3503dfd700 source=XrdFstOfsFile:2985 tident=monalisa.37670:34@pcalimonitor.cern.ch sec= uid=99 gid=99 name=nobody geo="" (write) checksum type: adler checksum hex: 00000001 requested-checksum hex: -none-
210127 15:22:36 time=1611760956.503600 func=Close level=ERROR logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f3503dfd700 source=ReplicaParLayout:500 tident=monalisa.37670:34@pcalimonitor.cern.ch sec=unix uid=0 gid=0 name=monalisa geo="" error=failed to close replica root://eos-fst03.alice-af.wigner.hu:1095///04/36435/05422528-a162-11e8-b5f9-a310691b2def?&authz=-----BEGIN SEALED CIPHER-----
kyIBuFKGp037QhPii63Txp+LUTIi-FgvSG-r6iZ7jfLE0c1NHl9ErotTokm2XVheoDFX6WyRgHRg
WtZAVbypLS8kwLkjljSdwJngzrzn7LMWUVt921dBJ3bX+Z-b92scVyaE2LoqXXGb4sll3s-XBfQJ
8VDc6io0n4cM8hLVM4k=
-----END SEALED CIPHER-----
-----BEGIN SEALED ENVELOPE-----
AAAAgAdghkuH1VV-7Y6LZzYApRzJqRxF8Tgzht2KAEkuEHJ0ntXP2Jsgpp+4c7CtU5K3Yoaj+5wm
LON4axCF+H5d7FMAa3J41Q59Kf6c5l+BR9cMRqtwCoHJfWVl0xs5B9oAVx5wwFHJRhwtv-RWZwTL
z1SuaSyKZbZ0ll6Igiu24jr8kpa-LMbZKsFGW42piid4f-yLWcZNIJo84kBd3FpuL+ED6D0OmjlD
iiEpQHTm1QcluG8p0srOzDcHCGeRyR0+gdZWzUQTXGQx9POjb8aZUWdPALJP4z3PE08Y0V8BtmCO
y45DDQruneu4FEySQxvABf2yT8t5vbT1NXErSxE1hykTzJplkdBBwBcpAC-G6E4MJtcnqvUvbEmd
lz8SlEr24IGzEQEO5W9+3apONFZeJyqB1OI4snAmWuhol-+YHs49Q2m929wlT6ynKgku76Dq7Rf-
tUxhHAFKTTDvDZAc0K7NiyrjJ5NhiNMmMnYIfSYTOZhdIIWFSfo7Tso37OwCkAUCJzwp-z-6WvMC
XUS9f8VnlG2gHXJQpFe+j3QgToIP0RGJQf7cixgZfm7yIKhibLZNYXtfd-h+4SuZVPL3ktIJNvtl
Iq0ilMzWyKu6Za4oZA5L9yE2WBwStWkiIG9Hanu8yLt1EC9bmurOuFegKsGjM6zzYKj0o6xqc5sQ
RA14fk3hEiFeqnky+FOV75LFZY7iTsmS1pe8ORIqQBN25g398MCuneaMQU3uCNXTEgRCIQ+LpVBo
erfuVUHNZHLTr-as6K0f-bxOU7GSFdu5GwuFfYoUfYkl3mPQb5sxTH4PHDx+w1tzHGjoADSSzXF3
7wA8OeJfyP0aBmkuonhbMLVUdWGRhWYY92Q1VD7o9M4rszAk4+oZ8V2Ocq+i3u7pj3dzldxGOJYT
EbOo5VgRslyBqRcT+GA6g2miPqnkD78cw5b3e3TaIPRQx1rDDOeqV0eIi69f+uuhSqqwUEcK9ZVd
+rlhSqWg2D0Th-ZYltO4dBQ+ukzQvNjN4tUbX3yFj7CKZqbZuUsA3juN3kd0XbI=
-----END SEALED ENVELOPE-----
&cap.msg=mm5ZFzWiq3JRALntMVlE67QqQ1Y/z9M4GlVddHQ8lSvar2J3bM/dgXEGEBJNNDFO9PbSkLr8mW1XkVBvdhEmxhL3oMtDoDBiYVtJHor74XMpj1Y5fHis29XIlTQ7eQplqCS69O4D7rFmAZiCMJODVpeHwgANkDjFi1VnGswa7ZKl4b3NWatC6NHsoR/S1nmCtvwCC1oqpfiShpSN/Iol9bcF/QjZbrhUA/dzq5v7euAN/aaIWQ63imYQKUkZukK+Y7jPLWl0v+ORthyHB7fgkliqIFccBDP9ONiX/DVlhqkVrpjn5P5miLYgmjHSZfB7IlI0quvvVZQPEk0dEjfbNJEYDwNNxQFqqag96AVLtSBgcQ+VPMjgzK+cglwymSiXexrOobWB46JwBaxqO1DVg/UmZ0bXCYso5AWeNkI6/wF0Y4m+phQTmHwto+8zIKmyemCuX4l1AaAS3G4SIHOOCuZxjAn6QxA5lpp50aITBkaJRf8xFjS6dVw0tW9bqoEssfILe514eiGze9Jji1dcoHiwF8Mm+JEpD0zE2Oz1xbVPdK3oI2NUHuZ6zlAoIUw4s8whDD3eE7HSWnKsC35ZYbk0dsWC+M+SZukoc7lgmeL9qmJe/xR+5+DgA5SkRZLk7APc7Tr6RVm8kcKnGAZOVKyNLzX6S8MZ&cap.sym=U+X2aCUU4sfJgJalbo3iQ0KUXfc=&eos.app=transfer-3rd&mgm.id=00001b53&mgm.logid=7864482a-60b3-11eb-be60-00259074c8e8&mgm.replicahead=0&mgm.replicaindex=1&oss.asize=249&tpc.dlg=eosalice.cern.ch:1094&tpc.dlgon=0&tpc.spr=root&tpc.str=1&tpc.tpr=root&mgm.path=/04/36435/05422528-a162-11e8-b5f9-a310691b2def
210127 15:22:36 2648 FstOfs_ReplicaParClose: monalisa.37670:34@pcalimonitor.cern.ch Unable to close failed ; remote I/O error
210127 15:22:36 time=1611760956.503706 func=_close level=INFO logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f3503dfd700 source=XrdFstOfsFile:1583 tident=monalisa.37670:34@pcalimonitor.cern.ch sec= uid=99 gid=99 name=nobody geo="" info="deleting on close" fn=/04/36435/05422528-a162-11e8-b5f9-a310691b2def fstpath=/data3/00000000/00001b53
210127 15:22:36 time=1611760956.503721 func=_rem level=INFO logid=17b13ab0-60ae-11eb-a52e-002590704734 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f3503dfd700 source=XrdFstOfs:1424 tident=<service> sec= uid=0 gid=0 name= geo="" fstpath=/data3/00000000/00001b53
210127 15:22:36 2648 FstOfs_stat: monalisa.37670:34@pcalimonitor.cern.ch Unable to locate /data3/00000000/00001b53; no such file or directory
210127 15:22:36 2648 FstOfs_remove: monalisa.37670:34@pcalimonitor.cern.ch Unable to remove /data3/00000000/00001b53; no such file or directory
210127 15:22:36 time=1611760956.503784 func=_rem level=INFO logid=17b13ab0-60ae-11eb-a52e-002590704734 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f3503dfd700 source=XrdFstOfs:1439 tident=<service> sec= uid=0 gid=0 name= geo="" rc=-1, errno=2
210127 15:22:36 2648 FstOfs__close: monalisa.37670:34@pcalimonitor.cern.ch Unable to store file - file has been cleaned because the stored file does not match the provided targetsize /04/36435/05422528-a162-11e8-b5f9-a310691b2def; input/output error
210127 15:22:36 time=1611760956.503875 func=_close level=WARN logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f3503dfd700 source=XrdFstOfsFile:1675 tident=monalisa.37670:34@pcalimonitor.cern.ch sec= uid=99 gid=99 name=nobody geo="" info="deleting on close" fn=/eos/alice/grid/04/36435/05422528-a162-11e8-b5f9-a310691b2def fstpath=/data3/00000000/00001b53 reason="target size mismatch"
210127 15:22:36 time=1611760956.503889 func=_close level=INFO logid=7864482a-60b3-11eb-be60-00259074c8e8 unit=fst@eos-fst06.alice-af.wigner.hu:1095 tid=00007f3503dfd700 source=XrdFstOfsFile:1792 tident=monalisa.37670:34@pcalimonitor.cern.ch sec= uid=99 gid=99 name=nobody geo="" msg="done close" rc=-1 errc=5
210127 15:22:36 2648 XrootdXeq: monalisa.37670:34@pcalimonitor.cern.ch disc 0:00:06
Hi Gabor,
Could you please paste the output of the following command?
cat /proc/<fst_pid>/environ
from this machine eos-fst06.alice-af.wigner.hu. The <fst_pid> is the process id for the FST daemon.
Thanks,
Elvin
Hi Elvin,
This is the output:
[root@eos-fst06 ~]# cat /proc/2640/environ
EOS_MGM_HOST=eos-mgm1.alice-af.wigner.huSHELL=/bin/shEOS_HTTP_THREADPOOL=epollLD_PRELOAD=/usr/lib64/libjemalloc.so.1EOS_FST_HTTP_PORT=8001DAEMON_COREFILE_LIMIT=unlimitedEOS_MGM_MASTER1=eos-mgm1.alice-af.wigner.huUSER=rootEOS_MGM_MASTER2=eos-mgm1.alice-af.wigner.huEOS_BROKER_URL=root://eos-mgm1.alice-af.wigner.hu:1097//eos/EOS_HTTP_CONNECTION_MEMORY_LIMIT=4194304EOS_NS_BOOT_PARALLEL=1EOS_MAIL_CC=biro.gabor@wigner.huEOS_GEOTAG=::KFKIEOS_AUTOLOAD_CONFIG=defaultPATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/binKRB5RCACHETYPE=nonePWD=/var/eosEOS_PSS_MGM=$EOS_MGM_ALIAS:1094XRD_ROLES=fstLANG=en_US.UTF-8EOS_NOTIFY=mail -s `date +%s`-`hostname`-eos-notify $EOS_MAIL_CCEOS_PSS_PORT=1098EOS_TTY_BROACAST_EGREP="CRIT|ALERT|EMERG|PROGRESS"EOS_MGM_HTTP_PORT=8000EOS_HTTP_CONNECTION_TIMEOUT=30SHLVL=1HOME=/rootEOS_PSS_PATH=/EOS_FST_NO_SSS_ENFORCEMENT=1EOS_TTY_BROADCAST_LISTEN_LOGFILE=/var/log/eos/mgm/xrdlog.mgmLOGNAME=rootEOS_FUSE_MGM_ALIAS=eos-mgm1.alice-af.wigner.huEOS_HTTP_THREADPOOL_SIZE=16EOS_FED_MANAGER=eos.cern.ch:1094EOS_INSTANCE_NAME=eosaliceEOS_MGM_ALIAS=eos-mgm1.alice-af.wigner.hu_=/opt/eos/xrootd/bin/xrootd
Hi Gabor,
We need to gather more info on why the connection to one of the CERN EOS FST is failing. To do this you need to enable XRootD debug logging. Please do this briefly on the FSTs until one of the ALICE transfers is done and then you can revert this change - the issue here it that this produces a lot of output.
Please set the following in your /etc/sysconfig/eos_env
XRD_LOGLEVEL=Dump
Afterwards send me the logs or even better the entire FST log file corresponding to one such transfer.
Thanks,
Elvin
Hi Elvin,
You can access the logs here: CERNBox
The failed transfer occurred around 08:22:30-08:22-38, but I also kept everything from before, starting with a service restart. It seems that fst05 and fst06 were involved, I included the logs of those machines.
Thanks,
Gabor
Hi Gabor,
The problem seems to be that it takes more than 5 seconds to establish a connection between your FST and one the the CERN EOS FSTs.
[2021-01-28 08:22:37.433013 +0000][Error ][AsyncSock ] [st-096-dd907c42.cern.ch:1095 #0.0] Socket error while handshaking: [ERROR] Socket timeout
[2021-01-28 08:22:37.433037 +0000][Debug ][AsyncSock ] [st-096-dd907c42.cern.ch:1095 #0.0] Closing the socket
[2021-01-28 08:22:37.433049 +0000][Debug ][Poller ] <x><--><x> Removing socket from the poller
[2021-01-28 08:22:37.433086 +0000][Error ][PostMaster ] [st-096-dd907c42.cern.ch:1095 #0] elapsed = 6, pConnectionWindow = 5 seconds.
[2021-01-28 08:22:37.433099 +0000][Error ][PostMaster ] [st-096-dd907c42.cern.ch:1095 #0] Unable to recover: [ERROR] Socket timeout.
[2021-01-28 08:22:37.433110 +0000][Error ][XRootD ] [st-096-dd907c42.cern.ch:1095] Impossible to send message kXR_open (file: /04/36435/05422528-a162-11e8-b5f9-a310691b2def?fst.readahead=true&fst.valid=1611822210&tpc.key=2c979a3c9b5a488b60127446&tpc.org=monalisa.18571@pcalimonitor.cern.ch, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ). Trying to recover.
Unfortunately, the XRD_CONNECTIONWINDOW timeout value is set in the FST code to 5 seconds and this will overwrite any environment variable that we might set. By default in the XRootD client this is 120 seconds but for performance reasons it lowered it in EOS. I will add a commit to allow the env variable to override the defaults we set in EOS.
It would probably be helpful to understand why it takes so long to establish a TCP connection from your FSTs to CERN - maybe network issues?! I will send you an update when I add support for the env variable override.
Thanks,
Elvin
Hi Gabor,
This is just to let you know that the functionality I mentioned i.e. have XRD_* env vars override the default values used inside EOS is not implemented by the following commit:
This will be available in EOS-4.8.38.
Cheers,
Elvin
Hi Elvin,
Thanks for this update, I’ll investigate the issue on our side. On the other hand, the TPC config itself should be ok in principle then… Of course if I understand that increasing the time limit is not a good solution, but it would be reassuring to see if it works or not.
Thanks,
Gabor