Mgm Error: Failed to load key from Configstore

sarric · April 11, 2024, 3:02am

Hello,
We have install eos version 5.2.21 on Rocky 9.3, we fusex mount eos on client, and try to write and read a file, but it hangs for while and finally failed, we found something wrong on fst log " FST still misses the required capability key".

240410 17:25:29 time=1712741129.919928 func=ProcessTpcOpaque         level=ERROR logid=2819f36c-f71c-11ee-bb21-f46b8c0b1144 unit=fst@node2.cern.ch:1095 tid=00007fc38cffc640 source=XrdFstOfsFile:3205             tident=AAAAAAAE.93199:34@node3 sec=unix  uid=0 gid=0 name=root geo="" msg="FST still misses the required capability key"
240410 17:25:29 time=1712741129.919943 func=_close                   level=INFO  logid=2819f36c-f71c-11ee-bb21-f46b8c0b1144 unit=fst@node2.cern.ch:1095 tid=00007fc38cffc640 source=XrdFstOfsFile:2258             tident=AAAAAAAE.93199:34@node3 sec=unix  uid=0 gid=0 name=root geo="" msg="done close" rc=0 errc=0
240410 17:27:33 time=1712741253.012043 func=_rem                     level=INFO  logid=a11ad676-f714-11ee-a44a-f46b8c3026f0 unit=fst@node2.cern.ch:1095 tid=00007fc3799fd640 source=XrdFstOfs:1281                 tident=<service> sec=      uid=0 gid=0 name= geo="" fstpath=/mnt/fst29/00000000/00000069
240410 17:27:33 3946 FstOfs_stat: ? Unable to locate /mnt/fst29/00000000/00000069; no such file or directory
240410 17:27:33 3946 FstOfs_remove: ? Unable to remove /mnt/fst29/00000000/00000069; no such file or directory

we also noticed an error message in mgm log “Failed to load key from Configstore”, it seems we have errors in our configuration with the sss keys between the MGM and the FSTs, but I can’t identify which ones.

240410 15:40:09 time=1712734809.299873 func=get                      level=ERROR logid=8892405a-f70d-11ee-8227-f46b8c0b1144 unit=mgm@node1.cern.ch:1094 tid=00007fe73c5c2640 source=ConfigStore:76                 tident=<service> sec=      uid=0 gid=0 name= geo="" msg="failed to load key from Configstore" key="converter-max-threads" err="msg=Failed Numeric conversion" key= error_msg=Invalid argument
240410 15:40:09 time=1712734809.299888 func=get                      level=ERROR logid=8892405a-f70d-11ee-8227-f46b8c0b1144 unit=mgm@node1.cern.ch:1094 tid=00007fe73c5c2640 source=ConfigStore:76                 tident=<service> sec=      uid=0 gid=0 name= geo="" msg="failed to load key from Configstore" key="converter-max-queuesize" err="msg=Failed Numeric conversion" key= error_msg=Invalid argument

Best,
Sarric

sarric · April 12, 2024, 2:01am

These are my configurations in the eos cluster.
cluster servers:
node1.cern.ch: running as MGM, FST, QDB
node2.cern.ch: running as FST

node1.cern.ch configurations are the following:

[root@node1 ~]# grep -v '#' /etc/eos/config/generic/all | awk 'NF'
[init]
mkdir -p /var/run/eos/
chown daemon:root /var/run/eos/
mkdir -p /var/cache/eos/
chown daemon:root /var/cache/eos/
if [ -e /etc/eos.keytab ]; then chown daemon /etc/eos.keytab ; chmod 400 /etc/eos.keytab ; fi
mkdir -p /var/eos/md /var/eos/report
chmod 755 /var/eos /var/eos/report
mkdir -p /var/spool/eos/core/mgm /var/spool/eos/core/mq /var/spool/eos/core/fst /var/spool/eos/core/qdb /var/spool/eos/admin
mkdir -p /var/log/eos
chown -R daemon /var/spool/eos
find /var/log/eos -maxdepth 1 -type d -exec chown daemon {} \;
find /var/eos/ -maxdepth 1 -mindepth 1 -not -path "/var/eos/fs" -not -path "/var/eos/fusex" -type d -exec chown -R daemon {} \;
chmod -R 775 /var/spool/eos
mkdir -p /var/eos/auth /var/eos/stage
chown daemon /var/eos/auth /var/eos/stage
setfacl -m default:u:daemon:r /var/eos/auth/
[sysconfig]
SERVER_HOST=node1.cern.ch
INSTANCE_NAME=eosdev
GEO_TAG=local
EOS_USE_MQ_ON_QDB=1
EOS_XROOTD=/opt/eos/xrootd/
LD_LIBRARY_PATH=${EOS_XROOTD}/lib64:/opt/eos/grpc/lib64
LD_PRELOAD=/usr/lib64/libjemalloc.so

[root@node1 ~]# grep -v '#' /etc/eos/config/qdb/qdb | awk 'NF'
[sysconfig]
QDB_HOST=${SERVER_HOST}
QDB_PORT=7777
QDB_CLUSTER_ID=${INSTANCE_NAME}
QDB_NODE=node1.cern.ch:7777
QDB_NODES=${QDB_HOST}:${QDB_PORT}
QDB_PATH=/var/lib/qdb
[init]
test -d ${QDB_PATH} || quarkdb-create --path ${QDB_PATH} --clusterID ${QDB_CLUSTER_ID} --nodes ${QDB_NODES}
chown -R daemon:daemon ${QDB_PATH}
[qdb:xrootd:qdb]
xrd.port ${QDB_PORT}
xrd.protocol redis:${QDB_PORT} libXrdQuarkDB.so
redis.database /var/lib/qdb
redis.mode raft
redis.myself ${QDB_NODE}
redis.password_file /etc/eos.keytab

[root@node1 ~]# grep -v '#' /etc/eos/config/mgm/mgm | awk 'NF'
[mgm:xrootd:mgm]
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
sec.protocol unix
sec.protocol sss -c /etc/eos.keytab -s /etc/eos.keytab
sec.protbind [::ffff:127.0.0.1] unix sss
sec.protbind localhost.localdomain unix sss
sec.protbind localhost unix sss
sec.protbind * only sss unix
sec.protbind 51.10.64.181 sss
mgmofs.fs /
mgmofs.targetport 1095
mgmofs.broker ${EOS_BROKER_URL}
mgmofs.instance ${EOS_INSTANCE_NAME}
mgmofs.metalog /var/eos/md
mgmofs.txdir /var/eos/tx
mgmofs.authdir /var/eos/auth
mgmofs.archivedir /var/eos/archive
mgmofs.qosdir /var/eos/qos
mgmofs.reportstorepath /var/eos/report
mgmofs.autoloadconfig default
mgmofs.qoscfg /var/eos/qos/qos.conf
mgmofs.fstgw someproxy.cern.ch:3001
mgmofs.nslib /usr/lib64/libEosNsQuarkdb.so
mgmofs.qdbcluster localhost:7777
mgmofs.qdbpassword_file /etc/eos.keytab
[sysconfig]
DAEMON_COREFILE_LIMIT=unlimited
LD_PRELOAD=/usr/lib64/libjemalloc.so
KRB5RCACHETYPE=none
KRB5=
GSI=
EOS_MGM_HOST=${SERVER_HOST}
EOS_MGM_HOST_TARGET=${SERVER_HOST}
EOS_START_SYNC_SEPARATELY=1
EOS_INSTANCE_NAME=${INSTANCE_NAME}
EOS_AUTOLOAD_CONFIG=default
EOS_BROKER_URL=root://localhost:1097//eos/
EOS_GEOTAG=${GEO_TAG}
EOS_MGM_MASTER1=${SERVER_HOST}
EOS_MGM_MASTER2=${SERVER_HOST}
EOS_MGM_ALIAS=${SERVER_HOST}
EOS_NO_STACKTRACE=1
EOS_UTF8=""
EOS_NS_ACCOUNTING=1
EOS_SYNCTIME_ACCOUNTING=1
EOS_MGM_LISTING_CACHE=0
EOS_ALLOW_SAME_HOST_IN_GROUP=1
EOS_MGM_HTTP_PORT=8000
EOS_HTTP_THREADPOOL=epoll
EOS_HTTP_THREADPOOL_SIZE=16
EOS_HTTP_CONNECTION_MEMORY_LIMIT=4194304
EOS_MGM_FUSEX_MAX_CHILDREN=262144
XDG_CACHE_HOME=/var/cache/eos/

[root@node1 ~]# grep -v '#' /etc/eos/config/fst/fst | awk 'NF'
[sysconfig]
EOS_XRDCP=${EOS_XROOTD}/bin/xrdcp
EOS_MGM_ALIAS=${SERVER_HOST}
EOS_GEOTAG=local::geo
QDB_HOST=node1.cern.ch
QDB_PORT=7777
[unshare]
[fst:xrootd:fst]
xrd.network keepalive
xrd.port 1095
xrootd.fslib -2 libXrdEosFst.so
xrootd.async off nosf
xrootd.redirect ${EOS_MGM_ALIAS}: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.persist off
ofs.osslib libEosFstOss.so
ofs.tpc pgm ${EOS_XRDCP}
fstofs.broker root://node1.cern.ch:1097//eos/
fstofs.autoboot true
fstofs.quotainterval 10
fstofs.metalog /var/eos/md/
fstofs.filemd_handler attr
fstofs.qdbcluster ${QDB_HOST}:${QDB_PORT}
fstofs.qdbpassword_file  /etc/eos.keytab

node2.cern.ch configurations are the following:

[root@node2 fst]# grep -v '#' /etc/eos/config/generic/all | awk 'NF'
[init]
mkdir -p /var/run/eos/
chown daemon:root /var/run/eos/
mkdir -p /var/cache/eos/
chown daemon:root /var/cache/eos/
if [ -e /etc/eos.keytab ]; then chown daemon /etc/eos.keytab ; chmod 400 /etc/eos.keytab ; fi
mkdir -p /var/eos/md /var/eos/report
chmod 755 /var/eos /var/eos/report
mkdir -p /var/spool/eos/core/mgm /var/spool/eos/core/mq /var/spool/eos/core/fst /var/spool/eos/core/qdb /var/spool/eos/admin
mkdir -p /var/log/eos
chown -R daemon /var/spool/eos
find /var/log/eos -maxdepth 1 -type d -exec chown daemon {} \;
find /var/eos/ -maxdepth 1 -mindepth 1 -not -path "/var/eos/fs" -not -path "/var/eos/fusex" -type d -exec chown -R daemon {} \;
chmod -R 775 /var/spool/eos
mkdir -p /var/eos/auth /var/eos/stage
chown daemon /var/eos/auth /var/eos/stage
setfacl -m default:u:daemon:r /var/eos/auth/
[sysconfig]
SERVER_HOST=node1.cern.ch
INSTANCE_NAME=eosdev
GEO_TAG=local
EOS_USE_MQ_ON_QDB=1
EOS_XROOTD=/opt/eos/xrootd/
LD_LIBRARY_PATH=${EOS_XROOTD}/lib64:/opt/eos/grpc/lib64
LD_PRELOAD=/usr/lib64/libjemalloc.so

[root@node2 fst]# grep -v '#' /etc/eos/config/generic/all | awk 'NF'
[init]
mkdir -p /var/run/eos/
chown daemon:root /var/run/eos/
mkdir -p /var/cache/eos/
chown daemon:root /var/cache/eos/
if [ -e /etc/eos.keytab ]; then chown daemon /etc/eos.keytab ; chmod 400 /etc/eos.keytab ; fi
mkdir -p /var/eos/md /var/eos/report
chmod 755 /var/eos /var/eos/report
mkdir -p /var/spool/eos/core/mgm /var/spool/eos/core/mq /var/spool/eos/core/fst /var/spool/eos/core/qdb /var/spool/eos/admin
mkdir -p /var/log/eos
chown -R daemon /var/spool/eos
find /var/log/eos -maxdepth 1 -type d -exec chown daemon {} \;
find /var/eos/ -maxdepth 1 -mindepth 1 -not -path "/var/eos/fs" -not -path "/var/eos/fusex" -type d -exec chown -R daemon {} \;
chmod -R 775 /var/spool/eos
mkdir -p /var/eos/auth /var/eos/stage
chown daemon /var/eos/auth /var/eos/stage
setfacl -m default:u:daemon:r /var/eos/auth/
[sysconfig]
SERVER_HOST=node1.cern.ch
INSTANCE_NAME=eosdev
GEO_TAG=local
EOS_USE_MQ_ON_QDB=1
EOS_XROOTD=/opt/eos/xrootd/
LD_LIBRARY_PATH=${EOS_XROOTD}/lib64:/opt/eos/grpc/lib64
LD_PRELOAD=/usr/lib64/libjemalloc.so
[root@node2 fst]# grep -v '#' /etc/eos/config/fst/fst | awk 'NF'
[sysconfig]
EOS_XRDCP=${EOS_XROOTD}/bin/xrdcp
EOS_MGM_ALIAS=${SERVER_HOST}
EOS_GEOTAG=local::geo
QDB_HOST=node1.cern.ch
QDB_PORT=7777
[unshare]
[fst:xrootd:fst]
xrd.network keepalive
xrd.port 1095
xrootd.fslib -2 libXrdEosFst.so
xrootd.async off nosf
xrootd.redirect ${EOS_MGM_ALIAS}: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.persist off
ofs.osslib libEosFstOss.so
ofs.tpc pgm ${EOS_XRDCP}
fstofs.broker root://node1.cern.ch:1097//eos/
fstofs.autoboot true
fstofs.quotainterval 10
fstofs.metalog /var/eos/md/
fstofs.filemd_handler attr
fstofs.qdbcluster ${QDB_HOST}:${QDB_PORT}
fstofs.qdbpassword_file  /etc/eos.keytab

the status of the cluster is following:

[root@node1 ~]# eos status
instance: eosdev
          health:     OK       
          nodes:      fst       2 online on
          versions:   mgm       1 5.2.21-1
                      qdb       1 5.2.21.1
                      fst       2 5.2.21-1

services:          
                      node1.cern.ch:1094 (active)
                      namespace [booted] [0 s]
                      qdb [GREEN]

storage:  data:       default    (0.00 PB total / 0.00 PB used 0.00 PB free / 0.00 PB avail )
          meta-data:  23 files 26 directories
          groups:               1 default on
          filesystems:          6   stat
          scheduler:      80% (fill limit)

clients:  4 clients
          auth:                 2 sss   (XRoot)
          io:          IN  OUT

          fuse :      1 clients (0 active) caps 0 locked 0
                      0.00 MB/s IN 65.00 MB/s OUT 0 kIOPS 7 MB RSS
                      v:        1 5.2.21           volatile
                      t:        1 static           
                      h:

if you have any further information, please let me know. Thanks!

Best regardsn
Sarric

esindril · April 12, 2024, 11:32am

Hi Sarric,

The error messages in the MGM being unable to load some keys from the configuration are harmless.

The messages on the FST side that you pasted in the initial comment come from different transfers. One that worked and one Third-Party-Copy which failed.

Can you try a simple xrdcp write/read and let me know if you have any issues with that? If so please send me the logs of the failing xrdcp command using -d 3 option and then we can debug from there.

Thanks,
Elvin

sarric · April 12, 2024, 12:27pm

Hi Elvin,
I tried a simple xrdcp on a separate client node3.cern.ch, with the following steps:

[root@node3 ~]# mount -t fuse eosxd -ofsname=node1.cern.ch:/eos/ /mnt/eostest/
# fsname='node1.cern.ch:/eos/'
# -o allow_other enabled on shared mount
# -o big_writes enabled
# no config file - running on default values
# no config file for local overwrites
# extracted remote mount dir from fsname is '/eos/'
# extracted connection host from fsname is 'node1.cern.ch'
# enabling swapping inodes with md-cache in '/var/cache/eos/fusex/md-cache/'
# File descriptor limit: 524288 soft, 524288 hard
# allowing max read-ahead buffers of 134217728 bytes
# allowing max write-back buffers of 134217728 bytes
# concurrent mount detect enabled, lock prefix /var/run/eos/fusex/mount.-mnt-eostest
# Disabling nagle algorithm (XRD_NODELAY=1)
# Setting MALLOC_CONF=dirty_decay_ms:0
[root@node3 ~]# 
[root@node3 ~]# df -h
Filesystem           Size  Used Avail Use% Mounted on
devtmpfs             4.0M     0  4.0M   0% /dev
tmpfs                158G     0  158G   0% /dev/shm
tmpfs                 63G  154M   63G   1% /run
/dev/sda4             70G  8.7G   62G  13% /
/dev/sda2            960M  262M  698M  28% /boot
/dev/sda1            599M  7.1M  592M   2% /boot/efi
/dev/sda5            1.1T   18G 1023G   2% /home
tmpfs                 32G   36K   32G   1% /run/user/0
node1.cern.ch:/eos/  480T  3.4T  477T   1% /mnt/eostest
[root@node3 ~]#  /opt/eos/xrootd/bin/xrdcp -d 3 /tmp/testfile /mnt/eostest/dev/testfile
[2024-04-12 20:18:22.667859 +0800][Dump   ][App               ] Chunk size: 8388608, parallel chunks 4, streams: 1
[2024-04-12 20:18:22.667903 +0800][Dump   ][App               ] Processing source entry: /tmp/testfile, type local file, target file: file:///mnt/eostest/dev/testfile
[2024-04-12 20:18:22.667961 +0800][Dump   ][Utility           ] Adding job with properties: 'checkSumMode' = 'none', 'checkSumPreset' = '', 'checkSumType' = '', 'chunkSize' = '8388608', 'coerce' = '0', 'continue' = '0', 'cpTimeout' = '0', 'delegate' = '0', 'doServer' = '0', 'dynamicSource' = '0', 'force' = '0', 'initTimeout' = '600', 'makeDir' = '0', 'parallelChunks' = '4', 'posc' = '0', 'preserveXAttr' = '0', 'rmOnBadCksum' = '0', 'source' = 'file:///tmp/testfile', 'target' = 'file:///mnt/eostest/dev/testfile', 'targetIsDir' = '0', 'thirdParty' = 'none', 'tpcTimeout' = '1800', 'xcp' = '0', 'xcpBlockSize' = '134217728', 'xrate' = '0', 'xrateThreshold' = '0', 'zipAppend' = '0', 'zipArchive' = '0'
[2024-04-12 20:18:22.667975 +0800][Debug  ][Utility           ] CopyProcess: 2 jobs to prepare
[2024-04-12 20:18:22.667991 +0800][Dump   ][Utility           ] URL: file:///tmp/testfile
[2024-04-12 20:18:22.667991 +0800][Dump   ][Utility           ] Protocol:  file
[2024-04-12 20:18:22.667991 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 20:18:22.667991 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 20:18:22.667991 +0800][Dump   ][Utility           ] Host Name: localhost
[2024-04-12 20:18:22.667991 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 20:18:22.667991 +0800][Dump   ][Utility           ] Path:      /tmp/testfile
[2024-04-12 20:18:22.668004 +0800][Dump   ][Utility           ] URL: file:///mnt/eostest/dev/testfile
[2024-04-12 20:18:22.668004 +0800][Dump   ][Utility           ] Protocol:  file
[2024-04-12 20:18:22.668004 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 20:18:22.668004 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 20:18:22.668004 +0800][Dump   ][Utility           ] Host Name: localhost
[2024-04-12 20:18:22.668004 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 20:18:22.668004 +0800][Dump   ][Utility           ] Path:      /mnt/eostest/dev/testfile
[2024-04-12 20:18:22.668020 +0800][Dump   ][Utility           ] URL: file:///tmp/testfile
[2024-04-12 20:18:22.668020 +0800][Dump   ][Utility           ] Protocol:  file
[2024-04-12 20:18:22.668020 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 20:18:22.668020 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 20:18:22.668020 +0800][Dump   ][Utility           ] Host Name: localhost
[2024-04-12 20:18:22.668020 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 20:18:22.668020 +0800][Dump   ][Utility           ] Path:      /tmp/testfile
[2024-04-12 20:18:22.668032 +0800][Dump   ][Utility           ] URL: file:///mnt/eostest/dev/testfile
[2024-04-12 20:18:22.668032 +0800][Dump   ][Utility           ] Protocol:  file
[2024-04-12 20:18:22.668032 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 20:18:22.668032 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 20:18:22.668032 +0800][Dump   ][Utility           ] Host Name: localhost
[2024-04-12 20:18:22.668032 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 20:18:22.668032 +0800][Dump   ][Utility           ] Path:      /mnt/eostest/dev/testfile
[2024-04-12 20:18:22.668040 +0800][Debug  ][Utility           ] Creating a classic copy job, from file://localhost/tmp/testfile to file://localhost/mnt/eostest/dev/testfile
[2024-04-12 20:18:22.668050 +0800][Debug  ][Utility           ] Monitor library name not set. No monitoring
[2024-04-12 20:18:22.668084 +0800][Debug  ][Utility           ] Opening file://localhost/tmp/testfile for reading
[2024-04-12 20:18:22.668099 +0800][Dump   ][Utility           ] URL: file://localhost/tmp/testfile
[2024-04-12 20:18:22.668099 +0800][Dump   ][Utility           ] Protocol:  file
[2024-04-12 20:18:22.668099 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 20:18:22.668099 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 20:18:22.668099 +0800][Dump   ][Utility           ] Host Name: localhost
[2024-04-12 20:18:22.668099 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 20:18:22.668099 +0800][Dump   ][Utility           ] Path:      /tmp/testfile
[2024-04-12 20:18:22.668111 +0800][Dump   ][Utility           ] URL: file://localhost/tmp/testfile
[2024-04-12 20:18:22.668111 +0800][Dump   ][Utility           ] Protocol:  file
[2024-04-12 20:18:22.668111 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 20:18:22.668111 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 20:18:22.668111 +0800][Dump   ][Utility           ] Host Name: localhost
[2024-04-12 20:18:22.668111 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 20:18:22.668111 +0800][Dump   ][Utility           ] Path:      /tmp/testfile
[2024-04-12 20:18:22.668121 +0800][Dump   ][Utility           ] URL: file://localhost/tmp/testfile
[2024-04-12 20:18:22.668121 +0800][Dump   ][Utility           ] Protocol:  file
[2024-04-12 20:18:22.668121 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 20:18:22.668121 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 20:18:22.668121 +0800][Dump   ][Utility           ] Host Name: localhost
[2024-04-12 20:18:22.668121 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 20:18:22.668121 +0800][Dump   ][Utility           ] Path:      /tmp/testfile
[2024-04-12 20:18:22.668143 +0800][Debug  ][File              ] [0x1aafac0@file://localhost/tmp/testfile?xrdcl.requuid=1a776b20-ea1c-49bd-b35c-0006a0a8a458] Sending an open command
[2024-04-12 20:18:22.668170 +0800][Dump   ][Utility           ] URL: file://localhost/tmp/testfile?xrdcl.requuid=1a776b20-ea1c-49bd-b35c-0006a0a8a458
[2024-04-12 20:18:22.668170 +0800][Dump   ][Utility           ] Protocol:  file
[2024-04-12 20:18:22.668170 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 20:18:22.668170 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 20:18:22.668170 +0800][Dump   ][Utility           ] Host Name: localhost
[2024-04-12 20:18:22.668170 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 20:18:22.668170 +0800][Dump   ][Utility           ] Path:      /tmp/testfile
[2024-04-12 20:18:22.668198 +0800][Dump   ][Utility           ] URL: file://localhost/tmp/testfile?xrdcl.requuid=1a776b20-ea1c-49bd-b35c-0006a0a8a458
[2024-04-12 20:18:22.668198 +0800][Dump   ][Utility           ] Protocol:  file
[2024-04-12 20:18:22.668198 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 20:18:22.668198 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 20:18:22.668198 +0800][Dump   ][Utility           ] Host Name: localhost
[2024-04-12 20:18:22.668198 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 20:18:22.668198 +0800][Dump   ][Utility           ] Path:      /tmp/testfile
[2024-04-12 20:18:22.668218 +0800][Debug  ][Utility           ] Env: trying to get a non-existent string entry: pollerpreference
[2024-04-12 20:18:22.668225 +0800][Debug  ][Poller            ] Available pollers: built-in
[2024-04-12 20:18:22.668228 +0800][Debug  ][Poller            ] Attempting to create a poller according to preference: built-in
[2024-04-12 20:18:22.668232 +0800][Debug  ][Poller            ] Creating poller: built-in
[2024-04-12 20:18:22.668237 +0800][Debug  ][Poller            ] Creating and starting the built-in poller...
[2024-04-12 20:18:22.669086 +0800][Debug  ][Poller            ] Using 10 poller threads
[2024-04-12 20:18:22.669096 +0800][Debug  ][TaskMgr           ] Starting the task manager...
[2024-04-12 20:18:22.669120 +0800][Debug  ][TaskMgr           ] Task manager started
[2024-04-12 20:18:22.669125 +0800][Debug  ][JobMgr            ] Starting the job manager...
[2024-04-12 20:18:22.669186 +0800][Debug  ][JobMgr            ] Job manager started, 3 workers
[2024-04-12 20:18:22.669193 +0800][Debug  ][TaskMgr           ] Registering task: "FileTimer task" to be run at: [2024-04-12 20:18:22 +0800]
[2024-04-12 20:18:22.669246 +0800][Debug  ][File              ] [0x1aafac0@file://localhost/tmp/testfile?xrdcl.requuid=1a776b20-ea1c-49bd-b35c-0006a0a8a458] Open has returned with status [SUCCESS] 
[2024-04-12 20:18:22.669260 +0800][Debug  ][File              ] [0x1aafac0@file://localhost/tmp/testfile?xrdcl.requuid=1a776b20-ea1c-49bd-b35c-0006a0a8a458] successfully opened at localhost, handle: 0x7, session id: 1
[2024-04-12 20:18:22.669299 +0800][Debug  ][Utility           ] Opening file://localhost/mnt/eostest/dev/testfile?oss.asize=46 for writing
[2024-04-12 20:18:22.669309 +0800][Dump   ][Utility           ] URL: file://localhost/mnt/eostest/dev/testfile?oss.asize=46
[2024-04-12 20:18:22.669309 +0800][Dump   ][Utility           ] Protocol:  file
[2024-04-12 20:18:22.669309 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 20:18:22.669309 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 20:18:22.669309 +0800][Dump   ][Utility           ] Host Name: localhost
[2024-04-12 20:18:22.669309 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 20:18:22.669309 +0800][Dump   ][Utility           ] Path:      /mnt/eostest/dev/testfile
[2024-04-12 20:18:22.669322 +0800][Dump   ][Utility           ] URL: file://localhost/mnt/eostest/dev/testfile?oss.asize=46
[2024-04-12 20:18:22.669322 +0800][Dump   ][Utility           ] Protocol:  file
[2024-04-12 20:18:22.669322 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 20:18:22.669322 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 20:18:22.669322 +0800][Dump   ][Utility           ] Host Name: localhost
[2024-04-12 20:18:22.669322 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 20:18:22.669322 +0800][Dump   ][Utility           ] Path:      /mnt/eostest/dev/testfile
[2024-04-12 20:18:22.669333 +0800][Dump   ][Utility           ] URL: file://localhost/mnt/eostest/dev/testfile?oss.asize=46
[2024-04-12 20:18:22.669333 +0800][Dump   ][Utility           ] Protocol:  file
[2024-04-12 20:18:22.669333 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 20:18:22.669333 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 20:18:22.669333 +0800][Dump   ][Utility           ] Host Name: localhost
[2024-04-12 20:18:22.669333 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 20:18:22.669333 +0800][Dump   ][Utility           ] Path:      /mnt/eostest/dev/testfile
[2024-04-12 20:18:22.669347 +0800][Debug  ][File              ] [0x1afa6e0@file://localhost/mnt/eostest/dev/testfile?oss.asize=46&xrdcl.requuid=20f1d3ff-6800-4f62-bee5-787b23765b0e] Sending an open command
[2024-04-12 20:18:22.669359 +0800][Dump   ][Utility           ] URL: file://localhost/mnt/eostest/dev/testfile?oss.asize=46&xrdcl.requuid=20f1d3ff-6800-4f62-bee5-787b23765b0e
[2024-04-12 20:18:22.669359 +0800][Dump   ][Utility           ] Protocol:  file
[2024-04-12 20:18:22.669359 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 20:18:22.669359 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 20:18:22.669359 +0800][Dump   ][Utility           ] Host Name: localhost
[2024-04-12 20:18:22.669359 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 20:18:22.669359 +0800][Dump   ][Utility           ] Path:      /mnt/eostest/dev/testfile
[2024-04-12 20:18:22.669517 +0800][Error  ][File              ] Open: open failed: /mnt/eostest/dev/testfile: operation not permitted
[2024-04-12 20:18:22.669550 +0800][Debug  ][File              ] [0x1afa6e0@file://localhost/mnt/eostest/dev/testfile?oss.asize=46&xrdcl.requuid=20f1d3ff-6800-4f62-bee5-787b23765b0e] Open has returned with status [ERROR] Local error: permission denied
[2024-04-12 20:18:22.669564 +0800][Debug  ][File              ] [0x1afa6e0@file://localhost/mnt/eostest/dev/testfile?oss.asize=46&xrdcl.requuid=20f1d3ff-6800-4f62-bee5-787b23765b0e] Error while opening at localhost: [ERROR] Local error: permission denied
[2024-04-12 20:18:22.669591 +0800][Debug  ][File              ] [0x1aafac0@file://localhost/tmp/testfile?xrdcl.requuid=1a776b20-ea1c-49bd-b35c-0006a0a8a458] Sending a close command for handle 0x7 to localhost
[2024-04-12 20:18:22.669626 +0800][Debug  ][File              ] [0x1aafac0@file://localhost/tmp/testfile?xrdcl.requuid=1a776b20-ea1c-49bd-b35c-0006a0a8a458] Close returned from localhost with: [SUCCESS] 
[2024-04-12 20:18:22.669640 +0800][Dump   ][File              ] [0x1aafac0@file://localhost/tmp/testfile?xrdcl.requuid=1a776b20-ea1c-49bd-b35c-0006a0a8a458] Items in the fly 0, queued for recovery 0
[0B/0B][100%][==================================================][0B/s]  
Run: [ERROR] Local error: permission denied:  (destination)
[2024-04-12 20:18:22.669791 +0800][Debug  ][JobMgr            ] Stopping the job manager...
[2024-04-12 20:18:22.669796 +0800][Dump   ][JobMgr            ] Stopping worker #0...
[2024-04-12 20:18:22.669854 +0800][Dump   ][JobMgr            ] Worker #0 stopped
[2024-04-12 20:18:22.669858 +0800][Dump   ][JobMgr            ] Stopping worker #1...
[2024-04-12 20:18:22.669885 +0800][Dump   ][JobMgr            ] Worker #1 stopped
[2024-04-12 20:18:22.669888 +0800][Dump   ][JobMgr            ] Stopping worker #2...
[2024-04-12 20:18:22.669915 +0800][Dump   ][JobMgr            ] Worker #2 stopped
[2024-04-12 20:18:22.669918 +0800][Debug  ][JobMgr            ] Job manager stopped
[2024-04-12 20:18:22.669921 +0800][Debug  ][Poller            ] Stopping the poller...
[2024-04-12 20:18:22.670089 +0800][Debug  ][TaskMgr           ] Stopping the task manager...
[2024-04-12 20:18:22.670158 +0800][Debug  ][TaskMgr           ] Task manager stopped

If you need more information, please tell me.

Best,
Sarric

esindril · April 12, 2024, 12:34pm

Hi Sarric,

I’m more interested in direct XRootD access and not going through FUSE. Please try something like this:
xrdcp -d 3 /path/to/some/local/file root://eosmgm-host//eos/<your_instance>/directory/file

Thanks,
Elvin

sarric · April 12, 2024, 1:19pm

Hi Elvin,
I tried to xrdcp on separate client, the log is as following:

[root@node3 ~]# /opt/eos/xrootd/bin/xrdcp -d 3 /tmp/testfile root://node1.cern.ch:/eos/dev/testfile
[2024-04-12 21:16:49.452039 +0800][Dump   ][App               ] Chunk size: 8388608, parallel chunks 4, streams: 1
[2024-04-12 21:16:49.452090 +0800][Dump   ][Utility           ] URL: root://node1.cern.ch:/eos/dev/testfile
[2024-04-12 21:16:49.452090 +0800][Dump   ][Utility           ] Protocol:  root
[2024-04-12 21:16:49.452090 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 21:16:49.452090 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 21:16:49.452090 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
[2024-04-12 21:16:49.452090 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 21:16:49.452090 +0800][Dump   ][Utility           ] Path:      eos/dev/testfile
[2024-04-12 21:16:49.452105 +0800][Dump   ][Utility           ] URL: root://node1.cern.ch:1094/eos/dev/testfile
[2024-04-12 21:16:49.452105 +0800][Dump   ][Utility           ] Protocol:  root
[2024-04-12 21:16:49.452105 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 21:16:49.452105 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 21:16:49.452105 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
[2024-04-12 21:16:49.452105 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 21:16:49.452105 +0800][Dump   ][Utility           ] Path:      eos/dev/testfile
[2024-04-12 21:16:49.452118 +0800][Dump   ][Utility           ] URL: root://node1.cern.ch:1094/eos/dev/testfile
[2024-04-12 21:16:49.452118 +0800][Dump   ][Utility           ] Protocol:  root
[2024-04-12 21:16:49.452118 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 21:16:49.452118 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 21:16:49.452118 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
[2024-04-12 21:16:49.452118 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 21:16:49.452118 +0800][Dump   ][Utility           ] Path:      eos/dev/testfile
[2024-04-12 21:16:49.452128 +0800][Dump   ][Utility           ] URL: root://node1.cern.ch:1094/eos/dev/testfile
[2024-04-12 21:16:49.452128 +0800][Dump   ][Utility           ] Protocol:  root
[2024-04-12 21:16:49.452128 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 21:16:49.452128 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 21:16:49.452128 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
[2024-04-12 21:16:49.452128 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 21:16:49.452128 +0800][Dump   ][Utility           ] Path:      eos/dev/testfile
[2024-04-12 21:16:49.452153 +0800][Dump   ][FileSystem        ] [0x14bd110@node1.cern.ch:1094] Sending kXR_stat (path: eos/dev/testfile, flags: none)
[2024-04-12 21:16:49.452163 +0800][Debug  ][Utility           ] Env: trying to get a non-existent string entry: pollerpreference
[2024-04-12 21:16:49.452171 +0800][Debug  ][Poller            ] Available pollers: built-in
[2024-04-12 21:16:49.452174 +0800][Debug  ][Poller            ] Attempting to create a poller according to preference: built-in
[2024-04-12 21:16:49.452178 +0800][Debug  ][Poller            ] Creating poller: built-in
[2024-04-12 21:16:49.452183 +0800][Debug  ][Poller            ] Creating and starting the built-in poller...
[2024-04-12 21:16:49.453042 +0800][Debug  ][Poller            ] Using 10 poller threads
[2024-04-12 21:16:49.453051 +0800][Debug  ][TaskMgr           ] Starting the task manager...
[2024-04-12 21:16:49.453075 +0800][Debug  ][TaskMgr           ] Task manager started
[2024-04-12 21:16:49.453079 +0800][Debug  ][JobMgr            ] Starting the job manager...
[2024-04-12 21:16:49.453139 +0800][Debug  ][JobMgr            ] Job manager started, 3 workers
[2024-04-12 21:16:49.453146 +0800][Debug  ][TaskMgr           ] Registering task: "FileTimer task" to be run at: [2024-04-12 21:16:49 +0800]
[2024-04-12 21:16:49.453151 +0800][Dump   ][XRootD            ] [node1.cern.ch:1094] Sending message kXR_stat (path: eos/dev/testfile, flags: none)
[2024-04-12 21:16:49.453169 +0800][Debug  ][ExDbgMsg          ] [node1.cern.ch:1094] MsgHandler created: 0x14e1a10 (message: kXR_stat (path: eos/dev/testfile, flags: none) ).
[2024-04-12 21:16:49.453189 +0800][Dump   ][Utility           ] URL: node1.cern.ch:1094
[2024-04-12 21:16:49.453189 +0800][Dump   ][Utility           ] Protocol:  root
[2024-04-12 21:16:49.453189 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 21:16:49.453189 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 21:16:49.453189 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
[2024-04-12 21:16:49.453189 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 21:16:49.453189 +0800][Dump   ][Utility           ] Path:      
[2024-04-12 21:16:49.453202 +0800][Dump   ][Utility           ] URL: root://node1.cern.ch:1094/
[2024-04-12 21:16:49.453202 +0800][Dump   ][Utility           ] Protocol:  root
[2024-04-12 21:16:49.453202 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 21:16:49.453202 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 21:16:49.453202 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
[2024-04-12 21:16:49.453202 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 21:16:49.453202 +0800][Dump   ][Utility           ] Path:      
[2024-04-12 21:16:49.453214 +0800][Debug  ][PostMaster        ] Creating new channel to: root://node1.cern.ch:1094/
[2024-04-12 21:16:49.453373 +0800][Debug  ][PostMaster        ] [node1.cern.ch:1094] Stream parameters: Network Stack: IPAuto, Connection Window: 120, ConnectionRetry: 5, Stream Error Window: 1800
[2024-04-12 21:16:49.453392 +0800][Debug  ][TaskMgr           ] Registering task: "TickGeneratorTask for: root://node1.cern.ch:1094/" to be run at: [2024-04-12 21:17:04 +0800]
[2024-04-12 21:16:49.453403 +0800][Dump   ][PostMaster        ] [node1.cern.ch:1094] Sending message kXR_stat (path: eos/dev/testfile, flags: none) (0x14bd4d0) through substream 0 expecting answer at 0
[2024-04-12 21:16:49.453451 +0800][Debug  ][PostMaster        ] [node1.cern.ch:1094] Found 1 address(es): [::ffff:51.10.64.181]:1094
[2024-04-12 21:16:49.453468 +0800][Debug  ][AsyncSock         ] [node1.cern.ch:1094.0] Attempting connection to [::ffff:51.10.64.181]:1094
[2024-04-12 21:16:49.453490 +0800][Debug  ][Poller            ] Adding socket 0x14bd560 to the poller
[2024-04-12 21:16:49.453557 +0800][Debug  ][AsyncSock         ] [node1.cern.ch:1094.0] Async connection call returned
[2024-04-12 21:16:49.453588 +0800][Debug  ][XRootDTransport   ] [node1.cern.ch:1094.0] Sending out the initial hand shake + kXR_protocol
[2024-04-12 21:16:49.453602 +0800][Error  ][TlsMsg            ] Failed to initialize TLS context: CA directory does not exist.
[2024-04-12 21:16:49.453606 +0800][Debug  ][Utility           ] Env: overriding entry: notlsok=0 with 1
[2024-04-12 21:16:49.453624 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Wrote a message:  (0x5c001380), 44 bytes
[2024-04-12 21:16:49.453748 +0800][Dump   ][XRootDTransport   ] [msg: 0x5c0016e0] Expecting 8 bytes of message body
[2024-04-12 21:16:49.453753 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received message header, size: 8
[2024-04-12 21:16:49.453758 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received a message of 16 bytes
[2024-04-12 21:16:49.453765 +0800][Debug  ][XRootDTransport   ] [node1.cern.ch:1094.0] Got the server hand shake response (type: manager [], protocol version 511)
[2024-04-12 21:16:49.453817 +0800][Dump   ][XRootDTransport   ] [msg: 0x5c0016e0] Expecting 8 bytes of message body
[2024-04-12 21:16:49.453821 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received message header, size: 8
[2024-04-12 21:16:49.453825 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received a message of 16 bytes
[2024-04-12 21:16:49.453830 +0800][Debug  ][XRootDTransport   ] [node1.cern.ch:1094.0] kXR_protocol successful (type: manager [], protocol version 511)
[2024-04-12 21:16:49.453886 +0800][Debug  ][XRootDTransport   ] [node1.cern.ch:1094.0] Sending out kXR_login request, username: root, cgi: xrd.cc=ch&xrd.tz=8&xrd.appname=xrdcp&xrd.info=&xrd.hostname=node3.cern.ch&xrd.rn=5.6.9, dual-stack: false, private IPv4: false, private IPv6: false
[2024-04-12 21:16:49.453897 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Wrote a message:  (0x5c001810), 110 bytes
[2024-04-12 21:16:49.453955 +0800][Dump   ][XRootDTransport   ] [msg: 0x5c001380] Expecting 51 bytes of message body
[2024-04-12 21:16:49.453959 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received message header, size: 8
[2024-04-12 21:16:49.453963 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received a message of 59 bytes
[2024-04-12 21:16:49.453969 +0800][Debug  ][XRootDTransport   ] [node1.cern.ch:1094.0] Logged in, session: 12000000b16b01008601000012000000
[2024-04-12 21:16:49.453972 +0800][Debug  ][XRootDTransport   ] [node1.cern.ch:1094.0] Authentication is required: &P=sss,0.+13:/etc/eos.keytab&P=unix
[2024-04-12 21:16:49.453976 +0800][Debug  ][XRootDTransport   ] [node1.cern.ch:1094.0] Sending authentication data
[2024-04-12 21:16:49.455572 +0800][Debug  ][XRootDTransport   ] [node1.cern.ch:1094.0] Trying to authenticate using sss
[2024-04-12 21:16:49.456274 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Wrote a message:  (0x5c053dc0), 246 bytes
[2024-04-12 21:16:49.458572 +0800][Dump   ][XRootDTransport   ] [msg: 0x5c001810] Expecting 0 bytes of message body
[2024-04-12 21:16:49.458578 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received message header, size: 8
[2024-04-12 21:16:49.458582 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received a message of 8 bytes
[2024-04-12 21:16:49.458589 +0800][Debug  ][XRootDTransport   ] [node1.cern.ch:1094.0] Authenticated with sss.
[2024-04-12 21:16:49.458596 +0800][Debug  ][PostMaster        ] [node1.cern.ch:1094] Stream 0 connected (IPv4).
[2024-04-12 21:16:49.458602 +0800][Debug  ][Utility           ] Monitor library name not set. No monitoring
[2024-04-12 21:16:49.458613 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Wrote a message: kXR_stat (path: eos/dev/testfile, flags: none) (0x14bd4d0), 40 bytes
[2024-04-12 21:16:49.458620 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Successfully sent message: kXR_stat (path: eos/dev/testfile, flags: none) (0x14bd4d0).
[2024-04-12 21:16:49.458624 +0800][Dump   ][XRootD            ] [node1.cern.ch:1094] Message kXR_stat (path: eos/dev/testfile, flags: none) has been successfully sent.
[2024-04-12 21:16:49.458628 +0800][Debug  ][ExDbgMsg          ] [node1.cern.ch:1094] Moving MsgHandler: 0x14e1a10 (message: kXR_stat (path: eos/dev/testfile, flags: none) ) from out-queue to in-queue.
[2024-04-12 21:16:49.458634 +0800][Dump   ][PostMaster        ] [node1.cern.ch:1094.0] All messages consumed, disable uplink
[2024-04-12 21:16:49.458681 +0800][Dump   ][XRootDTransport   ] [msg: 0x5c002100] Expecting 60 bytes of message body
[2024-04-12 21:16:49.458685 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received message header for 0x5c002100 size: 8
[2024-04-12 21:16:49.458690 +0800][Debug  ][ExDbgMsg          ] [msg: 0x5c002100] Assigned MsgHandler: 0x14e1a10.
[2024-04-12 21:16:49.458694 +0800][Debug  ][ExDbgMsg          ] [handler: 0x14e1a10] Removed MsgHandler: 0x14e1a10 from the in-queue.
[2024-04-12 21:16:49.458698 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received message 0x5c002100 of 68 bytes
[2024-04-12 21:16:49.458704 +0800][Dump   ][PostMaster        ] [node1.cern.ch:1094] Handling received message: 0x5c002100.
[2024-04-12 21:16:49.458735 +0800][Dump   ][XRootD            ] [node1.cern.ch:1094] Got a kXR_error response to request kXR_stat (path: eos/dev/testfile, flags: none) [3010] Stating relative path 'eos/dev/testfile' is disallowed.
[2024-04-12 21:16:49.458752 +0800][Debug  ][XRootD            ] [node1.cern.ch:1094] Handling error while processing kXR_stat (path: eos/dev/testfile, flags: none): [ERROR] Error response: permission denied.
[2024-04-12 21:16:49.458763 +0800][Debug  ][ExDbgMsg          ] [node1.cern.ch:1094] Calling MsgHandler: 0x14e1a10 (message: kXR_stat (path: eos/dev/testfile, flags: none) ) with status: [ERROR] Error response: permission denied.
[2024-04-12 21:16:49.458774 +0800][Debug  ][ExDbgMsg          ] [node1.cern.ch:1094] Destroying MsgHandler: 0x14e1a10.
[2024-04-12 21:16:49.458782 +0800][Error  ][App               ] [ERROR] Error response: permission denied (destination)
[ERROR] Server responded with an error: [3010] Stating relative path 'eos/dev/testfile' is disallowed.

[2024-04-12 21:16:49.459084 +0800][Debug  ][JobMgr            ] Stopping the job manager...
[2024-04-12 21:16:49.459090 +0800][Dump   ][JobMgr            ] Stopping worker #0...
[2024-04-12 21:16:49.459146 +0800][Dump   ][JobMgr            ] Worker #0 stopped
[2024-04-12 21:16:49.459150 +0800][Dump   ][JobMgr            ] Stopping worker #1...
[2024-04-12 21:16:49.459180 +0800][Dump   ][JobMgr            ] Worker #1 stopped
[2024-04-12 21:16:49.459183 +0800][Dump   ][JobMgr            ] Stopping worker #2...
[2024-04-12 21:16:49.459212 +0800][Dump   ][JobMgr            ] Worker #2 stopped
[2024-04-12 21:16:49.459215 +0800][Debug  ][JobMgr            ] Job manager stopped
[2024-04-12 21:16:49.459218 +0800][Debug  ][Poller            ] Stopping the poller...
[2024-04-12 21:16:49.459390 +0800][Debug  ][TaskMgr           ] Stopping the task manager...
[2024-04-12 21:16:49.459459 +0800][Debug  ][TaskMgr           ] Task manager stopped
[2024-04-12 21:16:49.459468 +0800][Debug  ][AsyncSock         ] [node1.cern.ch:1094.0] Closing the socket
[2024-04-12 21:16:49.459473 +0800][Debug  ][Poller            ] <[::ffff:51.10.64.185]:50890><--><[::ffff:51.10.64.181]:1094> Removing socket from the poller
[2024-04-12 21:16:49.459487 +0800][Debug  ][PostMaster        ] [node1.cern.ch:1094] Destroying stream
[2024-04-12 21:16:49.459493 +0800][Debug  ][AsyncSock         ] [node1.cern.ch:1094.0] Closing the socket

Best,
Sarric

esindril · April 12, 2024, 1:44pm

Hi Sarric,

You are missing an extra slash (and an extra :) between the MGM hostname and the path so the transfer fails with this error:
[2024-04-12 21:16:49.458735 +0800][Dump ][XRootD ] [node1.cern.ch:1094] Got a kXR_error response to request kXR_stat (path: eos/dev/testfile, flags: none) [3010] Stating relative path 'eos/dev/testfile' is disallowed.

I am interested in the debug logs only if the transfers fails.
Also what was exactly the initial issue with your instance?

Cheers,
Elvin

sarric · April 12, 2024, 2:13pm

Hi Elvin,
Sorry for mistake, I tried the xrdcp again, and the log says: Run: [ERROR] Server responded with an error: [3010] Unable to open file /eos/dev/testfile; Operation not permitted (destination)
The detail log as following:

[root@node3 ~]# /opt/eos/xrootd/bin/xrdcp -d 3 /tmp/testfile root://node1.cern.ch//eos/dev/testfile > xrdcp.log 2>&1 &
[1] 118546
[root@node3 ~]# 
[1]+  Exit 54                 /opt/eos/xrootd/bin/xrdcp -d 3 /tmp/testfile root://node1.cern.ch//eos/dev/testfile > xrdcp.log 2>&1
[root@node3 ~]# cat xrdcp.log 
[2024-04-12 22:04:40.917494 +0800][Dump   ][App               ] Chunk size: 8388608, parallel chunks 4, streams: 1
[2024-04-12 22:04:40.917548 +0800][Dump   ][Utility           ] URL: root://node1.cern.ch//eos/dev/testfile
[2024-04-12 22:04:40.917548 +0800][Dump   ][Utility           ] Protocol:  root
[2024-04-12 22:04:40.917548 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 22:04:40.917548 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 22:04:40.917548 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
[2024-04-12 22:04:40.917548 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 22:04:40.917548 +0800][Dump   ][Utility           ] Path:      /eos/dev/testfile
[2024-04-12 22:04:40.917560 +0800][Dump   ][Utility           ] URL: root://node1.cern.ch:1094//eos/dev/testfile
[2024-04-12 22:04:40.917560 +0800][Dump   ][Utility           ] Protocol:  root
[2024-04-12 22:04:40.917560 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 22:04:40.917560 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 22:04:40.917560 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
[2024-04-12 22:04:40.917560 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 22:04:40.917560 +0800][Dump   ][Utility           ] Path:      /eos/dev/testfile
[2024-04-12 22:04:40.917570 +0800][Dump   ][Utility           ] URL: root://node1.cern.ch:1094//eos/dev/testfile
[2024-04-12 22:04:40.917570 +0800][Dump   ][Utility           ] Protocol:  root
[2024-04-12 22:04:40.917570 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 22:04:40.917570 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 22:04:40.917570 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
[2024-04-12 22:04:40.917570 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 22:04:40.917570 +0800][Dump   ][Utility           ] Path:      /eos/dev/testfile
[2024-04-12 22:04:40.917578 +0800][Dump   ][Utility           ] URL: root://node1.cern.ch:1094//eos/dev/testfile
[2024-04-12 22:04:40.917578 +0800][Dump   ][Utility           ] Protocol:  root
[2024-04-12 22:04:40.917578 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 22:04:40.917578 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 22:04:40.917578 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
[2024-04-12 22:04:40.917578 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 22:04:40.917578 +0800][Dump   ][Utility           ] Path:      /eos/dev/testfile
[2024-04-12 22:04:40.917600 +0800][Dump   ][FileSystem        ] [0x2037b20@node1.cern.ch:1094] Sending kXR_stat (path: /eos/dev/testfile, flags: none)
[2024-04-12 22:04:40.917610 +0800][Debug  ][Utility           ] Env: trying to get a non-existent string entry: pollerpreference
[2024-04-12 22:04:40.917617 +0800][Debug  ][Poller            ] Available pollers: built-in
[2024-04-12 22:04:40.917619 +0800][Debug  ][Poller            ] Attempting to create a poller according to preference: built-in
[2024-04-12 22:04:40.917622 +0800][Debug  ][Poller            ] Creating poller: built-in
[2024-04-12 22:04:40.917627 +0800][Debug  ][Poller            ] Creating and starting the built-in poller...
[2024-04-12 22:04:40.918475 +0800][Debug  ][Poller            ] Using 10 poller threads
[2024-04-12 22:04:40.918486 +0800][Debug  ][TaskMgr           ] Starting the task manager...
[2024-04-12 22:04:40.918509 +0800][Debug  ][TaskMgr           ] Task manager started
[2024-04-12 22:04:40.918513 +0800][Debug  ][JobMgr            ] Starting the job manager...
[2024-04-12 22:04:40.918572 +0800][Debug  ][JobMgr            ] Job manager started, 3 workers
[2024-04-12 22:04:40.918578 +0800][Debug  ][TaskMgr           ] Registering task: "FileTimer task" to be run at: [2024-04-12 22:04:40 +0800]
[2024-04-12 22:04:40.918582 +0800][Dump   ][XRootD            ] [node1.cern.ch:1094] Sending message kXR_stat (path: /eos/dev/testfile, flags: none)
[2024-04-12 22:04:40.918600 +0800][Debug  ][ExDbgMsg          ] [node1.cern.ch:1094] MsgHandler created: 0x205c470 (message: kXR_stat (path: /eos/dev/testfile, flags: none) ).
[2024-04-12 22:04:40.918624 +0800][Dump   ][Utility           ] URL: node1.cern.ch:1094
[2024-04-12 22:04:40.918624 +0800][Dump   ][Utility           ] Protocol:  root
[2024-04-12 22:04:40.918624 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 22:04:40.918624 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 22:04:40.918624 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
[2024-04-12 22:04:40.918624 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 22:04:40.918624 +0800][Dump   ][Utility           ] Path:      
[2024-04-12 22:04:40.918635 +0800][Dump   ][Utility           ] URL: root://node1.cern.ch:1094/
[2024-04-12 22:04:40.918635 +0800][Dump   ][Utility           ] Protocol:  root
[2024-04-12 22:04:40.918635 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 22:04:40.918635 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 22:04:40.918635 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
[2024-04-12 22:04:40.918635 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 22:04:40.918635 +0800][Dump   ][Utility           ] Path:      
[2024-04-12 22:04:40.918642 +0800][Debug  ][PostMaster        ] Creating new channel to: root://node1.cern.ch:1094/
[2024-04-12 22:04:40.918793 +0800][Debug  ][PostMaster        ] [node1.cern.ch:1094] Stream parameters: Network Stack: IPAuto, Connection Window: 120, ConnectionRetry: 5, Stream Error Window: 1800
[2024-04-12 22:04:40.918810 +0800][Debug  ][TaskMgr           ] Registering task: "TickGeneratorTask for: root://node1.cern.ch:1094/" to be run at: [2024-04-12 22:04:55 +0800]
[2024-04-12 22:04:40.918819 +0800][Dump   ][PostMaster        ] [node1.cern.ch:1094] Sending message kXR_stat (path: /eos/dev/testfile, flags: none) (0x2037ee0) through substream 0 expecting answer at 0
[2024-04-12 22:04:40.918865 +0800][Debug  ][PostMaster        ] [node1.cern.ch:1094] Found 1 address(es): [::ffff:51.10.64.181]:1094
[2024-04-12 22:04:40.918879 +0800][Debug  ][AsyncSock         ] [node1.cern.ch:1094.0] Attempting connection to [::ffff:51.10.64.181]:1094
[2024-04-12 22:04:40.918899 +0800][Debug  ][Poller            ] Adding socket 0x2037f80 to the poller
[2024-04-12 22:04:40.918971 +0800][Debug  ][AsyncSock         ] [node1.cern.ch:1094.0] Async connection call returned
[2024-04-12 22:04:40.919003 +0800][Debug  ][XRootDTransport   ] [node1.cern.ch:1094.0] Sending out the initial hand shake + kXR_protocol
[2024-04-12 22:04:40.919016 +0800][Error  ][TlsMsg            ] Failed to initialize TLS context: CA directory does not exist.
[2024-04-12 22:04:40.919019 +0800][Debug  ][Utility           ] Env: overriding entry: notlsok=0 with 1
[2024-04-12 22:04:40.919035 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Wrote a message:  (0x90001380), 44 bytes
[2024-04-12 22:04:40.919096 +0800][Dump   ][XRootDTransport   ] [msg: 0x900016e0] Expecting 8 bytes of message body
[2024-04-12 22:04:40.919099 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received message header, size: 8
[2024-04-12 22:04:40.919104 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received a message of 16 bytes
[2024-04-12 22:04:40.919109 +0800][Debug  ][XRootDTransport   ] [node1.cern.ch:1094.0] Got the server hand shake response (type: manager [], protocol version 511)
[2024-04-12 22:04:40.919160 +0800][Dump   ][XRootDTransport   ] [msg: 0x900016e0] Expecting 8 bytes of message body
[2024-04-12 22:04:40.919164 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received message header, size: 8
[2024-04-12 22:04:40.919167 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received a message of 16 bytes
[2024-04-12 22:04:40.919171 +0800][Debug  ][XRootDTransport   ] [node1.cern.ch:1094.0] kXR_protocol successful (type: manager [], protocol version 511)
[2024-04-12 22:04:40.919224 +0800][Debug  ][XRootDTransport   ] [node1.cern.ch:1094.0] Sending out kXR_login request, username: root, cgi: xrd.cc=ch&xrd.tz=8&xrd.appname=xrdcp&xrd.info=&xrd.hostname=node3.cern.ch&xrd.rn=5.6.9, dual-stack: false, private IPv4: false, private IPv6: false
[2024-04-12 22:04:40.919237 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Wrote a message:  (0x90001810), 110 bytes
[2024-04-12 22:04:40.919304 +0800][Dump   ][XRootDTransport   ] [msg: 0x90001380] Expecting 51 bytes of message body
[2024-04-12 22:04:40.919312 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received message header, size: 8
[2024-04-12 22:04:40.919315 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received a message of 59 bytes
[2024-04-12 22:04:40.919321 +0800][Debug  ][XRootDTransport   ] [node1.cern.ch:1094.0] Logged in, session: 19000000b16b0100bd01000019000000
[2024-04-12 22:04:40.919323 +0800][Debug  ][XRootDTransport   ] [node1.cern.ch:1094.0] Authentication is required: &P=sss,0.+13:/etc/eos.keytab&P=unix
[2024-04-12 22:04:40.919326 +0800][Debug  ][XRootDTransport   ] [node1.cern.ch:1094.0] Sending authentication data
[2024-04-12 22:04:40.920929 +0800][Debug  ][XRootDTransport   ] [node1.cern.ch:1094.0] Trying to authenticate using sss
[2024-04-12 22:04:40.921645 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Wrote a message:  (0x90053dc0), 246 bytes
[2024-04-12 22:04:40.922302 +0800][Dump   ][XRootDTransport   ] [msg: 0x90001810] Expecting 0 bytes of message body
[2024-04-12 22:04:40.922309 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received message header, size: 8
[2024-04-12 22:04:40.922312 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received a message of 8 bytes
[2024-04-12 22:04:40.922318 +0800][Debug  ][XRootDTransport   ] [node1.cern.ch:1094.0] Authenticated with sss.
[2024-04-12 22:04:40.922324 +0800][Debug  ][PostMaster        ] [node1.cern.ch:1094] Stream 0 connected (IPv4).
[2024-04-12 22:04:40.922329 +0800][Debug  ][Utility           ] Monitor library name not set. No monitoring
[2024-04-12 22:04:40.922340 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Wrote a message: kXR_stat (path: /eos/dev/testfile, flags: none) (0x2037ee0), 41 bytes
[2024-04-12 22:04:40.922346 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Successfully sent message: kXR_stat (path: /eos/dev/testfile, flags: none) (0x2037ee0).
[2024-04-12 22:04:40.922350 +0800][Dump   ][XRootD            ] [node1.cern.ch:1094] Message kXR_stat (path: /eos/dev/testfile, flags: none) has been successfully sent.
[2024-04-12 22:04:40.922352 +0800][Debug  ][ExDbgMsg          ] [node1.cern.ch:1094] Moving MsgHandler: 0x205c470 (message: kXR_stat (path: /eos/dev/testfile, flags: none) ) from out-queue to in-queue.
[2024-04-12 22:04:40.922358 +0800][Dump   ][PostMaster        ] [node1.cern.ch:1094.0] All messages consumed, disable uplink
[2024-04-12 22:04:40.922584 +0800][Dump   ][XRootDTransport   ] [msg: 0x90002100] Expecting 64 bytes of message body
[2024-04-12 22:04:40.922588 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received message header for 0x90002100 size: 8
[2024-04-12 22:04:40.922593 +0800][Debug  ][ExDbgMsg          ] [msg: 0x90002100] Assigned MsgHandler: 0x205c470.
[2024-04-12 22:04:40.922596 +0800][Debug  ][ExDbgMsg          ] [handler: 0x205c470] Removed MsgHandler: 0x205c470 from the in-queue.
[2024-04-12 22:04:40.922600 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received message 0x90002100 of 72 bytes
[2024-04-12 22:04:40.922604 +0800][Dump   ][PostMaster        ] [node1.cern.ch:1094] Handling received message: 0x90002100.
[2024-04-12 22:04:40.922636 +0800][Dump   ][XRootD            ] [node1.cern.ch:1094] Got a kXR_error response to request kXR_stat (path: /eos/dev/testfile, flags: none) [3011] Unable to stat /eos/dev/testfile; No such file or directory
[2024-04-12 22:04:40.922652 +0800][Debug  ][XRootD            ] [node1.cern.ch:1094] Handling error while processing kXR_stat (path: /eos/dev/testfile, flags: none): [ERROR] Error response: no such file or directory.
[2024-04-12 22:04:40.922662 +0800][Debug  ][ExDbgMsg          ] [node1.cern.ch:1094] Calling MsgHandler: 0x205c470 (message: kXR_stat (path: /eos/dev/testfile, flags: none) ) with status: [ERROR] Error response: no such file or directory.
[2024-04-12 22:04:40.922675 +0800][Debug  ][ExDbgMsg          ] [node1.cern.ch:1094] Destroying MsgHandler: 0x205c470.
[2024-04-12 22:04:40.922684 +0800][Dump   ][App               ] Processing source entry: /tmp/testfile, type local file, target file: root://node1.cern.ch//eos/dev/testfile
[2024-04-12 22:04:40.922738 +0800][Dump   ][Utility           ] Adding job with properties: 'checkSumMode' = 'none', 'checkSumPreset' = '', 'checkSumType' = '', 'chunkSize' = '8388608', 'coerce' = '0', 'continue' = '0', 'cpTimeout' = '0', 'delegate' = '0', 'doServer' = '0', 'dynamicSource' = '0', 'force' = '0', 'initTimeout' = '600', 'makeDir' = '0', 'parallelChunks' = '4', 'posc' = '0', 'preserveXAttr' = '0', 'rmOnBadCksum' = '0', 'source' = 'file:///tmp/testfile', 'target' = 'root://node1.cern.ch//eos/dev/testfile', 'targetIsDir' = '0', 'thirdParty' = 'none', 'tpcTimeout' = '1800', 'xcp' = '0', 'xcpBlockSize' = '134217728', 'xrate' = '0', 'xrateThreshold' = '0', 'zipAppend' = '0', 'zipArchive' = '0'
[2024-04-12 22:04:40.922748 +0800][Debug  ][Utility           ] CopyProcess: 2 jobs to prepare
[2024-04-12 22:04:40.922756 +0800][Dump   ][Utility           ] URL: file:///tmp/testfile
[2024-04-12 22:04:40.922756 +0800][Dump   ][Utility           ] Protocol:  file
[2024-04-12 22:04:40.922756 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 22:04:40.922756 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 22:04:40.922756 +0800][Dump   ][Utility           ] Host Name: localhost
[2024-04-12 22:04:40.922756 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 22:04:40.922756 +0800][Dump   ][Utility           ] Path:      /tmp/testfile
[2024-04-12 22:04:40.922765 +0800][Dump   ][Utility           ] URL: root://node1.cern.ch//eos/dev/testfile
[2024-04-12 22:04:40.922765 +0800][Dump   ][Utility           ] Protocol:  root
[2024-04-12 22:04:40.922765 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 22:04:40.922765 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 22:04:40.922765 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
[2024-04-12 22:04:40.922765 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 22:04:40.922765 +0800][Dump   ][Utility           ] Path:      /eos/dev/testfile
[2024-04-12 22:04:40.922775 +0800][Dump   ][Utility           ] URL: file:///tmp/testfile
[2024-04-12 22:04:40.922775 +0800][Dump   ][Utility           ] Protocol:  file
[2024-04-12 22:04:40.922775 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 22:04:40.922775 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 22:04:40.922775 +0800][Dump   ][Utility           ] Host Name: localhost
[2024-04-12 22:04:40.922775 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 22:04:40.922775 +0800][Dump   ][Utility           ] Path:      /tmp/testfile
[2024-04-12 22:04:40.922783 +0800][Dump   ][Utility           ] URL: root://node1.cern.ch//eos/dev/testfile
[2024-04-12 22:04:40.922783 +0800][Dump   ][Utility           ] Protocol:  root
[2024-04-12 22:04:40.922783 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 22:04:40.922783 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 22:04:40.922783 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
[2024-04-12 22:04:40.922783 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 22:04:40.922783 +0800][Dump   ][Utility           ] Path:      /eos/dev/testfile
[2024-04-12 22:04:40.922788 +0800][Debug  ][Utility           ] Creating a classic copy job, from file://localhost/tmp/testfile to root://node1.cern.ch:1094//eos/dev/testfile
[2024-04-12 22:04:40.922822 +0800][Debug  ][Utility           ] Opening file://localhost/tmp/testfile for reading
[2024-04-12 22:04:40.922832 +0800][Dump   ][Utility           ] URL: file://localhost/tmp/testfile
[2024-04-12 22:04:40.922832 +0800][Dump   ][Utility           ] Protocol:  file
[2024-04-12 22:04:40.922832 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 22:04:40.922832 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 22:04:40.922832 +0800][Dump   ][Utility           ] Host Name: localhost
[2024-04-12 22:04:40.922832 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 22:04:40.922832 +0800][Dump   ][Utility           ] Path:      /tmp/testfile
[2024-04-12 22:04:40.922846 +0800][Dump   ][Utility           ] URL: file://localhost/tmp/testfile
[2024-04-12 22:04:40.922846 +0800][Dump   ][Utility           ] Protocol:  file
[2024-04-12 22:04:40.922846 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 22:04:40.922846 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 22:04:40.922846 +0800][Dump   ][Utility           ] Host Name: localhost
[2024-04-12 22:04:40.922846 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 22:04:40.922846 +0800][Dump   ][Utility           ] Path:      /tmp/testfile
[2024-04-12 22:04:40.922852 +0800][Dump   ][Utility           ] URL: file://localhost/tmp/testfile
[2024-04-12 22:04:40.922852 +0800][Dump   ][Utility           ] Protocol:  file
[2024-04-12 22:04:40.922852 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 22:04:40.922852 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 22:04:40.922852 +0800][Dump   ][Utility           ] Host Name: localhost
[2024-04-12 22:04:40.922852 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 22:04:40.922852 +0800][Dump   ][Utility           ] Path:      /tmp/testfile
[2024-04-12 22:04:40.922869 +0800][Debug  ][File              ] [0x1ffcac0@file://localhost/tmp/testfile?xrdcl.requuid=3e59b63e-7d64-4f78-959b-c2f500b41d4e] Sending an open command
[2024-04-12 22:04:40.922885 +0800][Dump   ][Utility           ] URL: file://localhost/tmp/testfile?xrdcl.requuid=3e59b63e-7d64-4f78-959b-c2f500b41d4e
[2024-04-12 22:04:40.922885 +0800][Dump   ][Utility           ] Protocol:  file
[2024-04-12 22:04:40.922885 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 22:04:40.922885 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 22:04:40.922885 +0800][Dump   ][Utility           ] Host Name: localhost
[2024-04-12 22:04:40.922885 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 22:04:40.922885 +0800][Dump   ][Utility           ] Path:      /tmp/testfile
[2024-04-12 22:04:40.922907 +0800][Dump   ][Utility           ] URL: file://localhost/tmp/testfile?xrdcl.requuid=3e59b63e-7d64-4f78-959b-c2f500b41d4e
[2024-04-12 22:04:40.922907 +0800][Dump   ][Utility           ] Protocol:  file
[2024-04-12 22:04:40.922907 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 22:04:40.922907 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 22:04:40.922907 +0800][Dump   ][Utility           ] Host Name: localhost
[2024-04-12 22:04:40.922907 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 22:04:40.922907 +0800][Dump   ][Utility           ] Path:      /tmp/testfile
[2024-04-12 22:04:40.922954 +0800][Debug  ][File              ] [0x1ffcac0@file://localhost/tmp/testfile?xrdcl.requuid=3e59b63e-7d64-4f78-959b-c2f500b41d4e] Open has returned with status [SUCCESS] 
[2024-04-12 22:04:40.922966 +0800][Debug  ][File              ] [0x1ffcac0@file://localhost/tmp/testfile?xrdcl.requuid=3e59b63e-7d64-4f78-959b-c2f500b41d4e] successfully opened at localhost, handle: 0x27, session id: 1
[2024-04-12 22:04:40.922990 +0800][Debug  ][Utility           ] Opening root://node1.cern.ch:1094//eos/dev/testfile?oss.asize=46 for writing
[2024-04-12 22:04:40.923000 +0800][Dump   ][Utility           ] URL: root://node1.cern.ch:1094//eos/dev/testfile?oss.asize=46
[2024-04-12 22:04:40.923000 +0800][Dump   ][Utility           ] Protocol:  root
[2024-04-12 22:04:40.923000 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 22:04:40.923000 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 22:04:40.923000 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
[2024-04-12 22:04:40.923000 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 22:04:40.923000 +0800][Dump   ][Utility           ] Path:      /eos/dev/testfile
[2024-04-12 22:04:40.923011 +0800][Dump   ][Utility           ] URL: root://node1.cern.ch:1094//eos/dev/testfile?oss.asize=46
[2024-04-12 22:04:40.923011 +0800][Dump   ][Utility           ] Protocol:  root
[2024-04-12 22:04:40.923011 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 22:04:40.923011 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 22:04:40.923011 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
[2024-04-12 22:04:40.923011 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 22:04:40.923011 +0800][Dump   ][Utility           ] Path:      /eos/dev/testfile
[2024-04-12 22:04:40.923018 +0800][Dump   ][Utility           ] URL: root://node1.cern.ch:1094//eos/dev/testfile?oss.asize=46
[2024-04-12 22:04:40.923018 +0800][Dump   ][Utility           ] Protocol:  root
[2024-04-12 22:04:40.923018 +0800][Dump   ][Utility           ] User Name: 
[2024-04-12 22:04:40.923018 +0800][Dump   ][Utility           ] Password:  
[2024-04-12 22:04:40.923018 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
[2024-04-12 22:04:40.923018 +0800][Dump   ][Utility           ] Port:      1094
[2024-04-12 22:04:40.923018 +0800][Dump   ][Utility           ] Path:      /eos/dev/testfile
[2024-04-12 22:04:40.923027 +0800][Debug  ][File              ] [0x2044550@root://node1.cern.ch:1094//eos/dev/testfile?oss.asize=46&xrdcl.requuid=f22afefd-09b7-42b3-9c95-f07f5aab153f] Sending an open command
[2024-04-12 22:04:40.923033 +0800][Dump   ][XRootD            ] [node1.cern.ch:1094] Sending message kXR_open (file: /eos/dev/testfile?oss.asize=46, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat )
[2024-04-12 22:04:40.923038 +0800][Debug  ][ExDbgMsg          ] [node1.cern.ch:1094] MsgHandler created: 0x2040400 (message: kXR_open (file: /eos/dev/testfile?oss.asize=46, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) ).
[2024-04-12 22:04:40.923043 +0800][Dump   ][PostMaster        ] [node1.cern.ch:1094] Sending message kXR_open (file: /eos/dev/testfile?oss.asize=46, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) (0x2048b00) through substream 0 expecting answer at 0
[2024-04-12 22:04:40.923055 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Wrote a message: kXR_open (file: /eos/dev/testfile?oss.asize=46, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) (0x2048b00), 54 bytes
[2024-04-12 22:04:40.923062 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Successfully sent message: kXR_open (file: /eos/dev/testfile?oss.asize=46, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) (0x2048b00).
[2024-04-12 22:04:40.923066 +0800][Dump   ][XRootD            ] [node1.cern.ch:1094] Message kXR_open (file: /eos/dev/testfile?oss.asize=46, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) has been successfully sent.
[2024-04-12 22:04:40.923069 +0800][Debug  ][ExDbgMsg          ] [node1.cern.ch:1094] Moving MsgHandler: 0x2040400 (message: kXR_open (file: /eos/dev/testfile?oss.asize=46, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) ) from out-queue to in-queue.
[2024-04-12 22:04:40.923071 +0800][Dump   ][PostMaster        ] [node1.cern.ch:1094.0] All messages consumed, disable uplink
[2024-04-12 22:04:40.923274 +0800][Dump   ][XRootDTransport   ] [msg: 0x90054150] Expecting 67 bytes of message body
[2024-04-12 22:04:40.923277 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received message header for 0x90054150 size: 8
[2024-04-12 22:04:40.923280 +0800][Debug  ][ExDbgMsg          ] [msg: 0x90054150] Assigned MsgHandler: 0x2040400.
[2024-04-12 22:04:40.923282 +0800][Debug  ][ExDbgMsg          ] [handler: 0x2040400] Removed MsgHandler: 0x2040400 from the in-queue.
[2024-04-12 22:04:40.923286 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received message 0x90054150 of 75 bytes
[2024-04-12 22:04:40.923294 +0800][Dump   ][PostMaster        ] [node1.cern.ch:1094] Handling received message: 0x90054150.
[2024-04-12 22:04:40.923323 +0800][Dump   ][XRootD            ] [node1.cern.ch:1094] Got a kXR_error response to request kXR_open (file: /eos/dev/testfile?oss.asize=46, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) [3010] Unable to open file /eos/dev/testfile; Operation not permitted
[2024-04-12 22:04:40.923340 +0800][Debug  ][XRootD            ] [node1.cern.ch:1094] Handling error while processing kXR_open (file: /eos/dev/testfile?oss.asize=46, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ): [ERROR] Error response: permission denied.
[2024-04-12 22:04:40.923346 +0800][Debug  ][ExDbgMsg          ] [node1.cern.ch:1094] Calling MsgHandler: 0x2040400 (message: kXR_open (file: /eos/dev/testfile?oss.asize=46, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) ) with status: [ERROR] Error response: permission denied.
[2024-04-12 22:04:40.923362 +0800][Debug  ][File              ] [0x2044550@root://node1.cern.ch:1094//eos/dev/testfile?oss.asize=46&xrdcl.requuid=f22afefd-09b7-42b3-9c95-f07f5aab153f] Open has returned with status [ERROR] Server responded with an error: [3010] Unable to open file /eos/dev/testfile; Operation not permitted
[2024-04-12 22:04:40.923367 +0800][Debug  ][File              ] [0x2044550@root://node1.cern.ch:1094//eos/dev/testfile?oss.asize=46&xrdcl.requuid=f22afefd-09b7-42b3-9c95-f07f5aab153f] Error while opening at node1.cern.ch:1094: [ERROR] Server responded with an error: [3010] Unable to open file /eos/dev/testfile; Operation not permitted
[2024-04-12 22:04:40.923375 +0800][Debug  ][ExDbgMsg          ] [node1.cern.ch:1094] Destroying MsgHandler: 0x2040400.
[2024-04-12 22:04:40.923389 +0800][Debug  ][File              ] [0x1ffcac0@file://localhost/tmp/testfile?xrdcl.requuid=3e59b63e-7d64-4f78-959b-c2f500b41d4e] Sending a close command for handle 0x27 to localhost
[2024-04-12 22:04:40.923407 +0800][Debug  ][File              ] [0x1ffcac0@file://localhost/tmp/testfile?xrdcl.requuid=3e59b63e-7d64-4f78-959b-c2f500b41d4e] Close returned from localhost with: [SUCCESS] 
[2024-04-12 22:04:40.923412 +0800][Dump   ][File              ] [0x1ffcac0@file://localhost/tmp/testfile?xrdcl.requuid=3e59b63e-7d64-4f78-959b-c2f500b41d4e] Items in the fly 0, queued for recovery 0
Run: [ERROR] Server responded with an error: [3010] Unable to open file /eos/dev/testfile; Operation not permitted (destination)

[2024-04-12 22:04:40.923715 +0800][Debug  ][JobMgr            ] Stopping the job manager...
[2024-04-12 22:04:40.923721 +0800][Dump   ][JobMgr            ] Stopping worker #0...
[2024-04-12 22:04:40.923778 +0800][Dump   ][JobMgr            ] Worker #0 stopped
[2024-04-12 22:04:40.923781 +0800][Dump   ][JobMgr            ] Stopping worker #1...
[2024-04-12 22:04:40.923810 +0800][Dump   ][JobMgr            ] Worker #1 stopped
[2024-04-12 22:04:40.923812 +0800][Dump   ][JobMgr            ] Stopping worker #2...
[2024-04-12 22:04:40.923838 +0800][Dump   ][JobMgr            ] Worker #2 stopped
[2024-04-12 22:04:40.923840 +0800][Debug  ][JobMgr            ] Job manager stopped
[2024-04-12 22:04:40.923843 +0800][Debug  ][Poller            ] Stopping the poller...
[2024-04-12 22:04:40.924006 +0800][Debug  ][TaskMgr           ] Stopping the task manager...
[2024-04-12 22:04:40.924074 +0800][Debug  ][TaskMgr           ] Task manager stopped
[2024-04-12 22:04:40.924082 +0800][Debug  ][AsyncSock         ] [node1.cern.ch:1094.0] Closing the socket
[2024-04-12 22:04:40.924087 +0800][Debug  ][Poller            ] <[::ffff:51.10.64.185]:58288><--><[::ffff:51.10.64.181]:1094> Removing socket from the poller
[2024-04-12 22:04:40.924098 +0800][Debug  ][PostMaster        ] [node1.cern.ch:1094] Destroying stream
[2024-04-12 22:04:40.924103 +0800][Debug  ][AsyncSock         ] [node1.cern.ch:1094.0] Closing the socket
[root@node3 ~]#

Meanwhile, I found the error in fst logs as following:

[root@node1 ~]# cat /var/log/eos/fst/xrdlog.fst |tail -n 20 | grep ERROR
240412 22:11:31 time=1712931091.609648 func=ProcessTpcOpaque         level=ERROR logid=89f8fca2-f8d6-11ee-8b65-f46b8c0b1144 unit=fst@node1.cern.ch:1095 tid=00007f9bff5f9640 source=XrdFstOfsFile:3205             tident=AAAAAAAE.117415:35@node3 sec=unix  uid=0 gid=0 name=root geo="" msg="FST still misses the required capability key"
240412 22:11:41 time=1712931101.610200 func=ProcessTpcOpaque         level=ERROR logid=89f8fca2-f8d6-11ee-8b65-f46b8c0b1144 unit=fst@node1.cern.ch:1095 tid=00007f9c005fb640 source=XrdFstOfsFile:3205             tident=AAAAAAAE.117415:35@node3 sec=unix  uid=0 gid=0 name=root geo="" msg="FST still misses the required capability key"
240412 22:11:51 time=1712931111.610699 func=ProcessTpcOpaque         level=ERROR logid=89f8fca2-f8d6-11ee-8b65-f46b8c0b1144 unit=fst@node1.cern.ch:1095 tid=00007f9c3e7fb640 source=XrdFstOfsFile:3205             tident=AAAAAAAE.117415:35@node3 sec=unix  uid=0 gid=0 name=root geo="" msg="FST still misses the required capability key"
240412 22:12:01 time=1712931121.611195 func=ProcessTpcOpaque         level=ERROR logid=89f8fca2-f8d6-11ee-8b65-f46b8c0b1144 unit=fst@node1.cern.ch:1095 tid=00007f9c00dfc640 source=XrdFstOfsFile:3205             tident=AAAAAAAE.117415:35@node3 sec=unix  uid=0 gid=0 name=root geo="" msg="FST still misses the required capability key"
240412 22:12:11 time=1712931131.611691 func=ProcessTpcOpaque         level=ERROR logid=89f8fca2-f8d6-11ee-8b65-f46b8c0b1144 unit=fst@node1.cern.ch:1095 tid=00007f9bff5f9640 source=XrdFstOfsFile:3205             tident=AAAAAAAE.117415:35@node3 sec=unix  uid=0 gid=0 name=root geo="" msg="FST still misses the required capability key"
240412 22:12:11 time=1712931131.725051 func=ProcessTpcOpaque         level=ERROR logid=a7d0f4f0-f8d6-11ee-9caf-f46b8c0b1144 unit=fst@node1.cern.ch:1095 tid=00007f9bff5f9640 source=XrdFstOfsFile:3205             tident=AAAAAAAE.117415:35@node3 sec=unix  uid=0 gid=0 name=root geo="" msg="FST still misses the required capability key"
240412 22:12:21 time=1712931141.612205 func=ProcessTpcOpaque         level=ERROR logid=a7d0f4f0-f8d6-11ee-9caf-f46b8c0b1144 unit=fst@node1.cern.ch:1095 tid=00007f9c005fb640 source=XrdFstOfsFile:3205             tident=AAAAAAAE.117415:35@node3 sec=unix  uid=0 gid=0 name=root geo="" msg="FST still misses the required capability key"

Please tell me if you need more infomation.

Best,
Sarric

sarric · April 15, 2024, 7:06am

Hi Elvin,
I tried again this morning to copy local file to eos via xrdcp , and found it stuck for a long time until l stopped it manully.
Since the xrdcp log size is large and I didn’t figure out a way to add the attachment file when editing the post, I’ll post it out in two parts.

[root@node3 ~]# /opt/eos/xrootd/bin/xrdcp -d 3 /tmp/testfile root://node1.cern.ch//eos/dev/testfile > xrdcp.log 2>&1 &
[root@node3 ~]# grep -n -B 200 "10:05:29.644644" xrdcp.log 
1-[2024-04-15 10:05:29.637652 +0800][Dump   ][App               ] Chunk size: 8388608, parallel chunks 4, streams: 1
2-[2024-04-15 10:05:29.637707 +0800][Dump   ][Utility           ] URL: root://node1.cern.ch//eos/dev/testfile
3-[2024-04-15 10:05:29.637707 +0800][Dump   ][Utility           ] Protocol:  root
4-[2024-04-15 10:05:29.637707 +0800][Dump   ][Utility           ] User Name: 
5-[2024-04-15 10:05:29.637707 +0800][Dump   ][Utility           ] Password:  
6-[2024-04-15 10:05:29.637707 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
7-[2024-04-15 10:05:29.637707 +0800][Dump   ][Utility           ] Port:      1094
8-[2024-04-15 10:05:29.637707 +0800][Dump   ][Utility           ] Path:      /eos/dev/testfile
9-[2024-04-15 10:05:29.637720 +0800][Dump   ][Utility           ] URL: root://node1.cern.ch:1094//eos/dev/testfile
10-[2024-04-15 10:05:29.637720 +0800][Dump   ][Utility           ] Protocol:  root
11-[2024-04-15 10:05:29.637720 +0800][Dump   ][Utility           ] User Name: 
12-[2024-04-15 10:05:29.637720 +0800][Dump   ][Utility           ] Password:  
13-[2024-04-15 10:05:29.637720 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
14-[2024-04-15 10:05:29.637720 +0800][Dump   ][Utility           ] Port:      1094
15-[2024-04-15 10:05:29.637720 +0800][Dump   ][Utility           ] Path:      /eos/dev/testfile
16-[2024-04-15 10:05:29.637730 +0800][Dump   ][Utility           ] URL: root://node1.cern.ch:1094//eos/dev/testfile
17-[2024-04-15 10:05:29.637730 +0800][Dump   ][Utility           ] Protocol:  root
18-[2024-04-15 10:05:29.637730 +0800][Dump   ][Utility           ] User Name: 
19-[2024-04-15 10:05:29.637730 +0800][Dump   ][Utility           ] Password:  
20-[2024-04-15 10:05:29.637730 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
21-[2024-04-15 10:05:29.637730 +0800][Dump   ][Utility           ] Port:      1094
22-[2024-04-15 10:05:29.637730 +0800][Dump   ][Utility           ] Path:      /eos/dev/testfile
23-[2024-04-15 10:05:29.637738 +0800][Dump   ][Utility           ] URL: root://node1.cern.ch:1094//eos/dev/testfile
24-[2024-04-15 10:05:29.637738 +0800][Dump   ][Utility           ] Protocol:  root
25-[2024-04-15 10:05:29.637738 +0800][Dump   ][Utility           ] User Name: 
26-[2024-04-15 10:05:29.637738 +0800][Dump   ][Utility           ] Password:  
27-[2024-04-15 10:05:29.637738 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
28-[2024-04-15 10:05:29.637738 +0800][Dump   ][Utility           ] Port:      1094
29-[2024-04-15 10:05:29.637738 +0800][Dump   ][Utility           ] Path:      /eos/dev/testfile
30-[2024-04-15 10:05:29.637761 +0800][Dump   ][FileSystem        ] [0x1213110@node1.cern.ch:1094] Sending kXR_stat (path: /eos/dev/testfile, flags: none)
31-[2024-04-15 10:05:29.637771 +0800][Debug  ][Utility           ] Env: trying to get a non-existent string entry: pollerpreference
32-[2024-04-15 10:05:29.637778 +0800][Debug  ][Poller            ] Available pollers: built-in
33-[2024-04-15 10:05:29.637780 +0800][Debug  ][Poller            ] Attempting to create a poller according to preference: built-in
34-[2024-04-15 10:05:29.637783 +0800][Debug  ][Poller            ] Creating poller: built-in
35-[2024-04-15 10:05:29.637788 +0800][Debug  ][Poller            ] Creating and starting the built-in poller...
36-[2024-04-15 10:05:29.638614 +0800][Debug  ][Poller            ] Using 10 poller threads
37-[2024-04-15 10:05:29.638625 +0800][Debug  ][TaskMgr           ] Starting the task manager...
38-[2024-04-15 10:05:29.638649 +0800][Debug  ][TaskMgr           ] Task manager started
39-[2024-04-15 10:05:29.638653 +0800][Debug  ][JobMgr            ] Starting the job manager...
40-[2024-04-15 10:05:29.638711 +0800][Debug  ][JobMgr            ] Job manager started, 3 workers
41-[2024-04-15 10:05:29.638717 +0800][Debug  ][TaskMgr           ] Registering task: "FileTimer task" to be run at: [2024-04-15 10:05:29 +0800]
42-[2024-04-15 10:05:29.638721 +0800][Dump   ][XRootD            ] [node1.cern.ch:1094] Sending message kXR_stat (path: /eos/dev/testfile, flags: none)
43-[2024-04-15 10:05:29.638740 +0800][Debug  ][ExDbgMsg          ] [node1.cern.ch:1094] MsgHandler created: 0x1237a10 (message: kXR_stat (path: /eos/dev/testfile, flags: none) ).
44-[2024-04-15 10:05:29.638765 +0800][Dump   ][Utility           ] URL: node1.cern.ch:1094
45-[2024-04-15 10:05:29.638765 +0800][Dump   ][Utility           ] Protocol:  root
46-[2024-04-15 10:05:29.638765 +0800][Dump   ][Utility           ] User Name: 
47-[2024-04-15 10:05:29.638765 +0800][Dump   ][Utility           ] Password:  
48-[2024-04-15 10:05:29.638765 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
49-[2024-04-15 10:05:29.638765 +0800][Dump   ][Utility           ] Port:      1094
50-[2024-04-15 10:05:29.638765 +0800][Dump   ][Utility           ] Path:      
51-[2024-04-15 10:05:29.638775 +0800][Dump   ][Utility           ] URL: root://node1.cern.ch:1094/
52-[2024-04-15 10:05:29.638775 +0800][Dump   ][Utility           ] Protocol:  root
53-[2024-04-15 10:05:29.638775 +0800][Dump   ][Utility           ] User Name: 
54-[2024-04-15 10:05:29.638775 +0800][Dump   ][Utility           ] Password:  
55-[2024-04-15 10:05:29.638775 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
56-[2024-04-15 10:05:29.638775 +0800][Dump   ][Utility           ] Port:      1094
57-[2024-04-15 10:05:29.638775 +0800][Dump   ][Utility           ] Path:      
58-[2024-04-15 10:05:29.638783 +0800][Debug  ][PostMaster        ] Creating new channel to: root://node1.cern.ch:1094/
59-[2024-04-15 10:05:29.638931 +0800][Debug  ][PostMaster        ] [node1.cern.ch:1094] Stream parameters: Network Stack: IPAuto, Connection Window: 120, ConnectionRetry: 5, Stream Error Window: 1800
60-[2024-04-15 10:05:29.638949 +0800][Debug  ][TaskMgr           ] Registering task: "TickGeneratorTask for: root://node1.cern.ch:1094/" to be run at: [2024-04-15 10:05:44 +0800]
61-[2024-04-15 10:05:29.638959 +0800][Dump   ][PostMaster        ] [node1.cern.ch:1094] Sending message kXR_stat (path: /eos/dev/testfile, flags: none) (0x12134d0) through substream 0 expecting answer at 0
62-[2024-04-15 10:05:29.639004 +0800][Debug  ][PostMaster        ] [node1.cern.ch:1094] Found 1 address(es): [::ffff:51.10.64.181]:1094
63-[2024-04-15 10:05:29.639019 +0800][Debug  ][AsyncSock         ] [node1.cern.ch:1094.0] Attempting connection to [::ffff:51.10.64.181]:1094
64-[2024-04-15 10:05:29.639039 +0800][Debug  ][Poller            ] Adding socket 0x1213570 to the poller
65-[2024-04-15 10:05:29.639105 +0800][Debug  ][AsyncSock         ] [node1.cern.ch:1094.0] Async connection call returned
66-[2024-04-15 10:05:29.639137 +0800][Debug  ][XRootDTransport   ] [node1.cern.ch:1094.0] Sending out the initial hand shake + kXR_protocol
67-[2024-04-15 10:05:29.639151 +0800][Error  ][TlsMsg            ] Failed to initialize TLS context: CA directory does not exist.
68-[2024-04-15 10:05:29.639154 +0800][Debug  ][Utility           ] Env: overriding entry: notlsok=0 with 1
69-[2024-04-15 10:05:29.639171 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Wrote a message:  (0xc001380), 44 bytes
70-[2024-04-15 10:05:29.639300 +0800][Dump   ][XRootDTransport   ] [msg: 0xc0016e0] Expecting 8 bytes of message body
71-[2024-04-15 10:05:29.639308 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received message header, size: 8
72-[2024-04-15 10:05:29.639312 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received a message of 16 bytes
73-[2024-04-15 10:05:29.639318 +0800][Debug  ][XRootDTransport   ] [node1.cern.ch:1094.0] Got the server hand shake response (type: manager [], protocol version 511)
74-[2024-04-15 10:05:29.639324 +0800][Dump   ][XRootDTransport   ] [msg: 0xc0016e0] Expecting 8 bytes of message body
75-[2024-04-15 10:05:29.639327 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received message header, size: 8
76-[2024-04-15 10:05:29.639330 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received a message of 16 bytes
77-[2024-04-15 10:05:29.639335 +0800][Debug  ][XRootDTransport   ] [node1.cern.ch:1094.0] kXR_protocol successful (type: manager [], protocol version 511)
78-[2024-04-15 10:05:29.639388 +0800][Debug  ][XRootDTransport   ] [node1.cern.ch:1094.0] Sending out kXR_login request, username: root, cgi: xrd.cc=ch&xrd.tz=8&xrd.appname=xrdcp&xrd.info=&xrd.hostname=node3.cern.ch&xrd.rn=5.6.9, dual-stack: false, private IPv4: false, private IPv6: false
79-[2024-04-15 10:05:29.639401 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Wrote a message:  (0xc001810), 110 bytes
80-[2024-04-15 10:05:29.639480 +0800][Dump   ][XRootDTransport   ] [msg: 0xc001380] Expecting 51 bytes of message body
81-[2024-04-15 10:05:29.639483 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received message header, size: 8
82-[2024-04-15 10:05:29.639487 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received a message of 59 bytes
83-[2024-04-15 10:05:29.639493 +0800][Debug  ][XRootDTransport   ] [node1.cern.ch:1094.0] Logged in, session: 20000000b16b01008601000020000000
84-[2024-04-15 10:05:29.639495 +0800][Debug  ][XRootDTransport   ] [node1.cern.ch:1094.0] Authentication is required: &P=sss,0.+13:/etc/eos.keytab&P=unix
85-[2024-04-15 10:05:29.639499 +0800][Debug  ][XRootDTransport   ] [node1.cern.ch:1094.0] Sending authentication data
86-[2024-04-15 10:05:29.641102 +0800][Debug  ][XRootDTransport   ] [node1.cern.ch:1094.0] Trying to authenticate using sss
87-[2024-04-15 10:05:29.641804 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Wrote a message:  (0xc053dc0), 246 bytes
88-[2024-04-15 10:05:29.643980 +0800][Dump   ][XRootDTransport   ] [msg: 0xc001810] Expecting 0 bytes of message body
89-[2024-04-15 10:05:29.643987 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received message header, size: 8
90-[2024-04-15 10:05:29.643990 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received a message of 8 bytes
91-[2024-04-15 10:05:29.643996 +0800][Debug  ][XRootDTransport   ] [node1.cern.ch:1094.0] Authenticated with sss.
92-[2024-04-15 10:05:29.644003 +0800][Debug  ][PostMaster        ] [node1.cern.ch:1094] Stream 0 connected (IPv4).
93-[2024-04-15 10:05:29.644007 +0800][Debug  ][Utility           ] Monitor library name not set. No monitoring
94-[2024-04-15 10:05:29.644017 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Wrote a message: kXR_stat (path: /eos/dev/testfile, flags: none) (0x12134d0), 41 bytes
95-[2024-04-15 10:05:29.644023 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Successfully sent message: kXR_stat (path: /eos/dev/testfile, flags: none) (0x12134d0).
96-[2024-04-15 10:05:29.644027 +0800][Dump   ][XRootD            ] [node1.cern.ch:1094] Message kXR_stat (path: /eos/dev/testfile, flags: none) has been successfully sent.
97-[2024-04-15 10:05:29.644029 +0800][Debug  ][ExDbgMsg          ] [node1.cern.ch:1094] Moving MsgHandler: 0x1237a10 (message: kXR_stat (path: /eos/dev/testfile, flags: none) ) from out-queue to in-queue.
98-[2024-04-15 10:05:29.644035 +0800][Dump   ][PostMaster        ] [node1.cern.ch:1094.0] All messages consumed, disable uplink
99-[2024-04-15 10:05:29.644202 +0800][Dump   ][XRootDTransport   ] [msg: 0xc002100] Expecting 64 bytes of message body
100-[2024-04-15 10:05:29.644206 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received message header for 0xc002100 size: 8
101-[2024-04-15 10:05:29.644211 +0800][Debug  ][ExDbgMsg          ] [msg: 0xc002100] Assigned MsgHandler: 0x1237a10.
102-[2024-04-15 10:05:29.644214 +0800][Debug  ][ExDbgMsg          ] [handler: 0x1237a10] Removed MsgHandler: 0x1237a10 from the in-queue.
103-[2024-04-15 10:05:29.644218 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received message 0xc002100 of 72 bytes
104-[2024-04-15 10:05:29.644223 +0800][Dump   ][PostMaster        ] [node1.cern.ch:1094] Handling received message: 0xc002100.
105-[2024-04-15 10:05:29.644255 +0800][Dump   ][XRootD            ] [node1.cern.ch:1094] Got a kXR_error response to request kXR_stat (path: /eos/dev/testfile, flags: none) [3011] Unable to stat /eos/dev/testfile; No such file or directory
106-[2024-04-15 10:05:29.644271 +0800][Debug  ][XRootD            ] [node1.cern.ch:1094] Handling error while processing kXR_stat (path: /eos/dev/testfile, flags: none): [ERROR] Error response: no such file or directory.
107-[2024-04-15 10:05:29.644282 +0800][Debug  ][ExDbgMsg          ] [node1.cern.ch:1094] Calling MsgHandler: 0x1237a10 (message: kXR_stat (path: /eos/dev/testfile, flags: none) ) with status: [ERROR] Error response: no such file or directory.
108-[2024-04-15 10:05:29.644299 +0800][Debug  ][ExDbgMsg          ] [node1.cern.ch:1094] Destroying MsgHandler: 0x1237a10.
109-[2024-04-15 10:05:29.644307 +0800][Dump   ][App               ] Processing source entry: /tmp/testfile, type local file, target file: root://node1.cern.ch//eos/dev/testfile
110-[2024-04-15 10:05:29.644363 +0800][Dump   ][Utility           ] Adding job with properties: 'checkSumMode' = 'none', 'checkSumPreset' = '', 'checkSumType' = '', 'chunkSize' = '8388608', 'coerce' = '0', 'continue' = '0', 'cpTimeout' = '0', 'delegate' = '0', 'doServer' = '0', 'dynamicSource' = '0', 'force' = '0', 'initTimeout' = '600', 'makeDir' = '0', 'parallelChunks' = '4', 'posc' = '0', 'preserveXAttr' = '0', 'rmOnBadCksum' = '0', 'source' = 'file:///tmp/testfile', 'target' = 'root://node1.cern.ch//eos/dev/testfile', 'targetIsDir' = '0', 'thirdParty' = 'none', 'tpcTimeout' = '1800', 'xcp' = '0', 'xcpBlockSize' = '134217728', 'xrate' = '0', 'xrateThreshold' = '0', 'zipAppend' = '0', 'zipArchive' = '0'
111-[2024-04-15 10:05:29.644374 +0800][Debug  ][Utility           ] CopyProcess: 2 jobs to prepare
112-[2024-04-15 10:05:29.644381 +0800][Dump   ][Utility           ] URL: file:///tmp/testfile
113-[2024-04-15 10:05:29.644381 +0800][Dump   ][Utility           ] Protocol:  file
114-[2024-04-15 10:05:29.644381 +0800][Dump   ][Utility           ] User Name: 
115-[2024-04-15 10:05:29.644381 +0800][Dump   ][Utility           ] Password:  
116-[2024-04-15 10:05:29.644381 +0800][Dump   ][Utility           ] Host Name: localhost
117-[2024-04-15 10:05:29.644381 +0800][Dump   ][Utility           ] Port:      1094
118-[2024-04-15 10:05:29.644381 +0800][Dump   ][Utility           ] Path:      /tmp/testfile
119-[2024-04-15 10:05:29.644391 +0800][Dump   ][Utility           ] URL: root://node1.cern.ch//eos/dev/testfile
120-[2024-04-15 10:05:29.644391 +0800][Dump   ][Utility           ] Protocol:  root
121-[2024-04-15 10:05:29.644391 +0800][Dump   ][Utility           ] User Name: 
122-[2024-04-15 10:05:29.644391 +0800][Dump   ][Utility           ] Password:  
123-[2024-04-15 10:05:29.644391 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
124-[2024-04-15 10:05:29.644391 +0800][Dump   ][Utility           ] Port:      1094
125-[2024-04-15 10:05:29.644391 +0800][Dump   ][Utility           ] Path:      /eos/dev/testfile
126-[2024-04-15 10:05:29.644401 +0800][Dump   ][Utility           ] URL: file:///tmp/testfile
127-[2024-04-15 10:05:29.644401 +0800][Dump   ][Utility           ] Protocol:  file
128-[2024-04-15 10:05:29.644401 +0800][Dump   ][Utility           ] User Name: 
129-[2024-04-15 10:05:29.644401 +0800][Dump   ][Utility           ] Password:  
130-[2024-04-15 10:05:29.644401 +0800][Dump   ][Utility           ] Host Name: localhost
131-[2024-04-15 10:05:29.644401 +0800][Dump   ][Utility           ] Port:      1094
132-[2024-04-15 10:05:29.644401 +0800][Dump   ][Utility           ] Path:      /tmp/testfile
133-[2024-04-15 10:05:29.644409 +0800][Dump   ][Utility           ] URL: root://node1.cern.ch//eos/dev/testfile
134-[2024-04-15 10:05:29.644409 +0800][Dump   ][Utility           ] Protocol:  root
135-[2024-04-15 10:05:29.644409 +0800][Dump   ][Utility           ] User Name: 
136-[2024-04-15 10:05:29.644409 +0800][Dump   ][Utility           ] Password:  
137-[2024-04-15 10:05:29.644409 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
138-[2024-04-15 10:05:29.644409 +0800][Dump   ][Utility           ] Port:      1094
139-[2024-04-15 10:05:29.644409 +0800][Dump   ][Utility           ] Path:      /eos/dev/testfile
140-[2024-04-15 10:05:29.644414 +0800][Debug  ][Utility           ] Creating a classic copy job, from file://localhost/tmp/testfile to root://node1.cern.ch:1094//eos/dev/testfile
141-[2024-04-15 10:05:29.644449 +0800][Debug  ][Utility           ] Opening file://localhost/tmp/testfile for reading
142-[2024-04-15 10:05:29.644458 +0800][Dump   ][Utility           ] URL: file://localhost/tmp/testfile
143-[2024-04-15 10:05:29.644458 +0800][Dump   ][Utility           ] Protocol:  file
144-[2024-04-15 10:05:29.644458 +0800][Dump   ][Utility           ] User Name: 
145-[2024-04-15 10:05:29.644458 +0800][Dump   ][Utility           ] Password:  
146-[2024-04-15 10:05:29.644458 +0800][Dump   ][Utility           ] Host Name: localhost
147-[2024-04-15 10:05:29.644458 +0800][Dump   ][Utility           ] Port:      1094
148-[2024-04-15 10:05:29.644458 +0800][Dump   ][Utility           ] Path:      /tmp/testfile
149-[2024-04-15 10:05:29.644472 +0800][Dump   ][Utility           ] URL: file://localhost/tmp/testfile
150-[2024-04-15 10:05:29.644472 +0800][Dump   ][Utility           ] Protocol:  file
151-[2024-04-15 10:05:29.644472 +0800][Dump   ][Utility           ] User Name: 
152-[2024-04-15 10:05:29.644472 +0800][Dump   ][Utility           ] Password:  
153-[2024-04-15 10:05:29.644472 +0800][Dump   ][Utility           ] Host Name: localhost
154-[2024-04-15 10:05:29.644472 +0800][Dump   ][Utility           ] Port:      1094
155-[2024-04-15 10:05:29.644472 +0800][Dump   ][Utility           ] Path:      /tmp/testfile
156-[2024-04-15 10:05:29.644479 +0800][Dump   ][Utility           ] URL: file://localhost/tmp/testfile
157-[2024-04-15 10:05:29.644479 +0800][Dump   ][Utility           ] Protocol:  file
158-[2024-04-15 10:05:29.644479 +0800][Dump   ][Utility           ] User Name: 
159-[2024-04-15 10:05:29.644479 +0800][Dump   ][Utility           ] Password:  
160-[2024-04-15 10:05:29.644479 +0800][Dump   ][Utility           ] Host Name: localhost
161-[2024-04-15 10:05:29.644479 +0800][Dump   ][Utility           ] Port:      1094
162-[2024-04-15 10:05:29.644479 +0800][Dump   ][Utility           ] Path:      /tmp/testfile
163-[2024-04-15 10:05:29.644495 +0800][Debug  ][File              ] [0x1227bb0@file://localhost/tmp/testfile?xrdcl.requuid=4fbf2f34-6db5-4214-b338-97ba4f19c021] Sending an open command
164-[2024-04-15 10:05:29.644511 +0800][Dump   ][Utility           ] URL: file://localhost/tmp/testfile?xrdcl.requuid=4fbf2f34-6db5-4214-b338-97ba4f19c021
165-[2024-04-15 10:05:29.644511 +0800][Dump   ][Utility           ] Protocol:  file
166-[2024-04-15 10:05:29.644511 +0800][Dump   ][Utility           ] User Name: 
167-[2024-04-15 10:05:29.644511 +0800][Dump   ][Utility           ] Password:  
168-[2024-04-15 10:05:29.644511 +0800][Dump   ][Utility           ] Host Name: localhost
169-[2024-04-15 10:05:29.644511 +0800][Dump   ][Utility           ] Port:      1094
170-[2024-04-15 10:05:29.644511 +0800][Dump   ][Utility           ] Path:      /tmp/testfile
171-[2024-04-15 10:05:29.644533 +0800][Dump   ][Utility           ] URL: file://localhost/tmp/testfile?xrdcl.requuid=4fbf2f34-6db5-4214-b338-97ba4f19c021
172-[2024-04-15 10:05:29.644533 +0800][Dump   ][Utility           ] Protocol:  file
173-[2024-04-15 10:05:29.644533 +0800][Dump   ][Utility           ] User Name: 
174-[2024-04-15 10:05:29.644533 +0800][Dump   ][Utility           ] Password:  
175-[2024-04-15 10:05:29.644533 +0800][Dump   ][Utility           ] Host Name: localhost
176-[2024-04-15 10:05:29.644533 +0800][Dump   ][Utility           ] Port:      1094
177-[2024-04-15 10:05:29.644533 +0800][Dump   ][Utility           ] Path:      /tmp/testfile
178-[2024-04-15 10:05:29.644578 +0800][Debug  ][File              ] [0x1227bb0@file://localhost/tmp/testfile?xrdcl.requuid=4fbf2f34-6db5-4214-b338-97ba4f19c021] Open has returned with status [SUCCESS] 
179-[2024-04-15 10:05:29.644590 +0800][Debug  ][File              ] [0x1227bb0@file://localhost/tmp/testfile?xrdcl.requuid=4fbf2f34-6db5-4214-b338-97ba4f19c021] successfully opened at localhost, handle: 0x27, session id: 1
180-[2024-04-15 10:05:29.644615 +0800][Debug  ][Utility           ] Opening root://node1.cern.ch:1094//eos/dev/testfile?oss.asize=46 for writing
181-[2024-04-15 10:05:29.644625 +0800][Dump   ][Utility           ] URL: root://node1.cern.ch:1094//eos/dev/testfile?oss.asize=46
182-[2024-04-15 10:05:29.644625 +0800][Dump   ][Utility           ] Protocol:  root
183-[2024-04-15 10:05:29.644625 +0800][Dump   ][Utility           ] User Name: 
184-[2024-04-15 10:05:29.644625 +0800][Dump   ][Utility           ] Password:  
185-[2024-04-15 10:05:29.644625 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
186-[2024-04-15 10:05:29.644625 +0800][Dump   ][Utility           ] Port:      1094
187-[2024-04-15 10:05:29.644625 +0800][Dump   ][Utility           ] Path:      /eos/dev/testfile
188-[2024-04-15 10:05:29.644636 +0800][Dump   ][Utility           ] URL: root://node1.cern.ch:1094//eos/dev/testfile?oss.asize=46
189-[2024-04-15 10:05:29.644636 +0800][Dump   ][Utility           ] Protocol:  root
190-[2024-04-15 10:05:29.644636 +0800][Dump   ][Utility           ] User Name: 
191-[2024-04-15 10:05:29.644636 +0800][Dump   ][Utility           ] Password:  
192-[2024-04-15 10:05:29.644636 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
193-[2024-04-15 10:05:29.644636 +0800][Dump   ][Utility           ] Port:      1094
194-[2024-04-15 10:05:29.644636 +0800][Dump   ][Utility           ] Path:      /eos/dev/testfile
195:[2024-04-15 10:05:29.644644 +0800][Dump   ][Utility           ] URL: root://node1.cern.ch:1094//eos/dev/testfile?oss.asize=46
196:[2024-04-15 10:05:29.644644 +0800][Dump   ][Utility           ] Protocol:  root
197:[2024-04-15 10:05:29.644644 +0800][Dump   ][Utility           ] User Name: 
198:[2024-04-15 10:05:29.644644 +0800][Dump   ][Utility           ] Password:  
199:[2024-04-15 10:05:29.644644 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
200:[2024-04-15 10:05:29.644644 +0800][Dump   ][Utility           ] Port:      1094
201:[2024-04-15 10:05:29.644644 +0800][Dump   ][Utility           ] Path:      /eos/dev/testfile
[root@node3 ~]#

sarric · April 15, 2024, 7:35am

This follows on from the log above.

[root@node3 ~]# grep -n -A 110 "10:05:29.644644" xrdcp.log 
195:[2024-04-15 10:05:29.644644 +0800][Dump   ][Utility           ] URL: root://node1.cern.ch:1094//eos/dev/testfile?oss.asize=46
196:[2024-04-15 10:05:29.644644 +0800][Dump   ][Utility           ] Protocol:  root
197:[2024-04-15 10:05:29.644644 +0800][Dump   ][Utility           ] User Name: 
198:[2024-04-15 10:05:29.644644 +0800][Dump   ][Utility           ] Password:  
199:[2024-04-15 10:05:29.644644 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
200:[2024-04-15 10:05:29.644644 +0800][Dump   ][Utility           ] Port:      1094
201:[2024-04-15 10:05:29.644644 +0800][Dump   ][Utility           ] Path:      /eos/dev/testfile
202-[2024-04-15 10:05:29.644653 +0800][Debug  ][File              ] [0x122be10@root://node1.cern.ch:1094//eos/dev/testfile?oss.asize=46&xrdcl.requuid=ff548f99-22e1-4742-8a95-ce2972ea38e9] Sending an open command
203-[2024-04-15 10:05:29.644659 +0800][Dump   ][XRootD            ] [node1.cern.ch:1094] Sending message kXR_open (file: /eos/dev/testfile?oss.asize=46, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat )
204-[2024-04-15 10:05:29.644664 +0800][Debug  ][ExDbgMsg          ] [node1.cern.ch:1094] MsgHandler created: 0x121b820 (message: kXR_open (file: /eos/dev/testfile?oss.asize=46, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) ).
205-[2024-04-15 10:05:29.644669 +0800][Dump   ][PostMaster        ] [node1.cern.ch:1094] Sending message kXR_open (file: /eos/dev/testfile?oss.asize=46, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) (0x1227fa0) through substream 0 expecting answer at 0
206-[2024-04-15 10:05:29.644681 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Wrote a message: kXR_open (file: /eos/dev/testfile?oss.asize=46, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) (0x1227fa0), 54 bytes
207-[2024-04-15 10:05:29.644688 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Successfully sent message: kXR_open (file: /eos/dev/testfile?oss.asize=46, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) (0x1227fa0).
208-[2024-04-15 10:05:29.644692 +0800][Dump   ][XRootD            ] [node1.cern.ch:1094] Message kXR_open (file: /eos/dev/testfile?oss.asize=46, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) has been successfully sent.
209-[2024-04-15 10:05:29.644695 +0800][Debug  ][ExDbgMsg          ] [node1.cern.ch:1094] Moving MsgHandler: 0x121b820 (message: kXR_open (file: /eos/dev/testfile?oss.asize=46, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) ) from out-queue to in-queue.
210-[2024-04-15 10:05:29.644697 +0800][Dump   ][PostMaster        ] [node1.cern.ch:1094.0] All messages consumed, disable uplink
211-[2024-04-15 10:05:29.645452 +0800][Dump   ][XRootDTransport   ] [msg: 0xc054150] Expecting 712 bytes of message body
212-[2024-04-15 10:05:29.645458 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received message header for 0xc054150 size: 8
213-[2024-04-15 10:05:29.645461 +0800][Debug  ][ExDbgMsg          ] [msg: 0xc054150] Assigned MsgHandler: 0x121b820.
214-[2024-04-15 10:05:29.645463 +0800][Debug  ][ExDbgMsg          ] [handler: 0x121b820] Removed MsgHandler: 0x121b820 from the in-queue.
215-[2024-04-15 10:05:29.645467 +0800][Dump   ][AsyncSock         ] [node1.cern.ch:1094.0] Received message 0xc054150 of 720 bytes
216-[2024-04-15 10:05:29.645470 +0800][Dump   ][PostMaster        ] [node1.cern.ch:1094] Handling received message: 0xc054150.
217-[2024-04-15 10:05:29.645499 +0800][Dump   ][XRootD            ] [node1.cern.ch:1094] Got kXR_redirect response to message kXR_open (file: /eos/dev/testfile?oss.asize=46, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ): node2.cern.ch?&cap.sym=pTJWNr6GA/LZgn7M4/uGj4P/haA=&cap.msg=iarIobHpITHH7mFmxoX7idszB2zfDKtifzPB6K+R6JS+RKsPlhvP/kBx+Mm93VS8+qRlKzLiXzUF/VOwqQcYSDU/uH5hzoLQKAX4Zd/hRLLkV/7Fyb+9LDxNOihyfV+URFtR+VNMifzrlpu949i7QOFICsR/vzPNRCJlaIgc3xxrTX0rhIt6PK54CIBAFXxrWUnDq35SUML2j4qcT/bsmU6FyyVCFFVI3uENk3VKbpFr2LzhkhS1QfYF94ahXeL1OpQP7Of2kLd3V05o1fD/PpnA2S/RXpJqLmU10p0GF+itM8hT50AYelRG0rJddDNBDihMhH+OmjzT+9LU1HFOcZ6/SYG9PRSuIb9d2saOEO3+6o3md+itMBdMhoilxgsxK9ZyIH11/iw=&mgm.logid=9ff2786a-facc-11ee-adf8-f46b8c0b1144&mgm.replicaindex=0&mgm.replicahead=0&mgm.id=00000073&eos.clientinfo=zbase64:MDAwMDAwNjF4nBXIUQqAIBBF0a20ArGiIGEWk/oGhRhlUqLdl3/n3lIhThtZs69TLs4/lIWH7pAQyQ62t4J8Z4YijlE1F4rgs19t9L+zIjSSErGYABUTkpvtsX2BAyH1, port 1095
218-[2024-04-15 10:05:29.645522 +0800][Dump   ][XRootD            ] [node1.cern.ch:1094] Current server has been assigned as a load-balancer for message kXR_open (file: /eos/dev/testfile?oss.asize=46, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat )
219-[2024-04-15 10:05:29.645533 +0800][Dump   ][Utility           ] URL: node2.cern.ch:1095/
220-[2024-04-15 10:05:29.645533 +0800][Dump   ][Utility           ] Protocol:  root
221-[2024-04-15 10:05:29.645533 +0800][Dump   ][Utility           ] User Name: 
222-[2024-04-15 10:05:29.645533 +0800][Dump   ][Utility           ] Password:  
223-[2024-04-15 10:05:29.645533 +0800][Dump   ][Utility           ] Host Name: node2.cern.ch
224-[2024-04-15 10:05:29.645533 +0800][Dump   ][Utility           ] Port:      1095
225-[2024-04-15 10:05:29.645533 +0800][Dump   ][Utility           ] Path:      
226-[2024-04-15 10:05:29.645558 +0800][Dump   ][Utility           ] URL: fake://fake:111//fake?&cap.sym=pTJWNr6GA/LZgn7M4/uGj4P/haA=&cap.msg=iarIobHpITHH7mFmxoX7idszB2zfDKtifzPB6K+R6JS+RKsPlhvP/kBx+Mm93VS8+qRlKzLiXzUF/VOwqQcYSDU/uH5hzoLQKAX4Zd/hRLLkV/7Fyb+9LDxNOihyfV+URFtR+VNMifzrlpu949i7QOFICsR/vzPNRCJlaIgc3xxrTX0rhIt6PK54CIBAFXxrWUnDq35SUML2j4qcT/bsmU6FyyVCFFVI3uENk3VKbpFr2LzhkhS1QfYF94ahXeL1OpQP7Of2kLd3V05o1fD/PpnA2S/RXpJqLmU10p0GF+itM8hT50AYelRG0rJddDNBDihMhH+OmjzT+9LU1HFOcZ6/SYG9PRSuIb9d2saOEO3+6o3md+itMBdMhoilxgsxK9ZyIH11/iw=&mgm.logid=9ff2786a-facc-11ee-adf8-f46b8c0b1144&mgm.replicaindex=0&mgm.replicahead=0&mgm.id=00000073&eos.clientinfo=zbase64:MDAwMDAwNjF4nBXIUQqAIBBF0a20ArGiIGEWk/oGhRhlUqLdl3/n3lIhThtZs69TLs4/lIWH7pAQyQ62t4J8Z4YijlE1F4rgs19t9L+zIjSSErGYABUTkpvtsX2BAyH1&xrdcl.requuid=ff548f99-22e1-4742-8a95-ce2972ea38e9&
227-[2024-04-15 10:05:29.645558 +0800][Dump   ][Utility           ] Protocol:  fake
228-[2024-04-15 10:05:29.645558 +0800][Dump   ][Utility           ] User Name: 
229-[2024-04-15 10:05:29.645558 +0800][Dump   ][Utility           ] Password:  
230-[2024-04-15 10:05:29.645558 +0800][Dump   ][Utility           ] Host Name: fake
231-[2024-04-15 10:05:29.645558 +0800][Dump   ][Utility           ] Port:      111
232-[2024-04-15 10:05:29.645558 +0800][Dump   ][Utility           ] Path:      /fake
233-[2024-04-15 10:05:29.645580 +0800][Dump   ][Utility           ] URL: fake://fake:111//eos/dev/testfile?oss.asize=46
234-[2024-04-15 10:05:29.645580 +0800][Dump   ][Utility           ] Protocol:  fake
235-[2024-04-15 10:05:29.645580 +0800][Dump   ][Utility           ] User Name: 
236-[2024-04-15 10:05:29.645580 +0800][Dump   ][Utility           ] Password:  
237-[2024-04-15 10:05:29.645580 +0800][Dump   ][Utility           ] Host Name: fake
238-[2024-04-15 10:05:29.645580 +0800][Dump   ][Utility           ] Port:      111
239-[2024-04-15 10:05:29.645580 +0800][Dump   ][Utility           ] Path:      /eos/dev/testfile
240-[2024-04-15 10:05:29.645606 +0800][Dump   ][Utility           ] URL: root://node1.cern.ch:1094//eos/dev/testfile
241-[2024-04-15 10:05:29.645606 +0800][Dump   ][Utility           ] Protocol:  root
242-[2024-04-15 10:05:29.645606 +0800][Dump   ][Utility           ] User Name: 
243-[2024-04-15 10:05:29.645606 +0800][Dump   ][Utility           ] Password:  
244-[2024-04-15 10:05:29.645606 +0800][Dump   ][Utility           ] Host Name: node1.cern.ch
245-[2024-04-15 10:05:29.645606 +0800][Dump   ][Utility           ] Port:      1094
246-[2024-04-15 10:05:29.645606 +0800][Dump   ][Utility           ] Path:      /eos/dev/testfile
247-[2024-04-15 10:05:29.645616 +0800][Dump   ][Utility           ] URL: root://node2.cern.ch:1095/
248-[2024-04-15 10:05:29.645616 +0800][Dump   ][Utility           ] Protocol:  root
249-[2024-04-15 10:05:29.645616 +0800][Dump   ][Utility           ] User Name: 
250-[2024-04-15 10:05:29.645616 +0800][Dump   ][Utility           ] Password:  
251-[2024-04-15 10:05:29.645616 +0800][Dump   ][Utility           ] Host Name: node2.cern.ch
252-[2024-04-15 10:05:29.645616 +0800][Dump   ][Utility           ] Port:      1095
253-[2024-04-15 10:05:29.645616 +0800][Dump   ][Utility           ] Path:      
254-[2024-04-15 10:05:29.645629 +0800][Debug  ][ExDbgMsg          ] [node2.cern.ch:1095] Retry at server MsgHandler: 0x121b820 (message: kXR_open (file: /eos/dev/testfile?cap.msg=iarIobHpITHH7mFmxoX7idszB2zfDKtifzPB6K+R6JS+RKsPlhvP/kBx+Mm93VS8+qRlKzLiXzUF/VOwqQcYSDU/uH5hzoLQKAX4Zd/hRLLkV/7Fyb+9LDxNOihyfV+URFtR+VNMifzrlpu949i7QOFICsR/vzPNRCJlaIgc3xxrTX0rhIt6PK54CIBAFXxrWUnDq35SUML2j4qcT/bsmU6FyyVCFFVI3uENk3VKbpFr2LzhkhS1QfYF94ahXeL1OpQP7Of2kLd3V05o1fD/PpnA2S/RXpJqLmU10p0GF+itM8hT50AYelRG0rJddDNBDihMhH+OmjzT+9LU1HFOcZ6/SYG9PRSuIb9d2saOEO3+6o3md+itMBdMhoilxgsxK9ZyIH11/iw=&cap.sym=pTJWNr6GA/LZgn7M4/uGj4P/haA=&eos.clientinfo=zbase64:MDAwMDAwNjF4nBXIUQqAIBBF0a20ArGiIGEWk/oGhRhlUqLdl3/n3lIhThtZs69TLs4/lIWH7pAQyQ62t4J8Z4YijlE1F4rgs19t9L+zIjSSErGYABUTkpvtsX2BAyH1&mgm.id=00000073&mgm.logid=9ff2786a-facc-11ee-adf8-f46b8c0b1144&mgm.replicahead=0&mgm.replicaindex=0&oss.asize=46, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) ).
255-[2024-04-15 10:05:29.645636 +0800][Dump   ][Utility           ] URL: node2.cern.ch:1095
256-[2024-04-15 10:05:29.645636 +0800][Dump   ][Utility           ] Protocol:  root
257-[2024-04-15 10:05:29.645636 +0800][Dump   ][Utility           ] User Name: 
258-[2024-04-15 10:05:29.645636 +0800][Dump   ][Utility           ] Password:  
259-[2024-04-15 10:05:29.645636 +0800][Dump   ][Utility           ] Host Name: node2.cern.ch
260-[2024-04-15 10:05:29.645636 +0800][Dump   ][Utility           ] Port:      1095
261-[2024-04-15 10:05:29.645636 +0800][Dump   ][Utility           ] Path:      
262-[2024-04-15 10:05:29.645645 +0800][Dump   ][Utility           ] URL: root://node2.cern.ch:1095/
263-[2024-04-15 10:05:29.645645 +0800][Dump   ][Utility           ] Protocol:  root
264-[2024-04-15 10:05:29.645645 +0800][Dump   ][Utility           ] User Name: 
265-[2024-04-15 10:05:29.645645 +0800][Dump   ][Utility           ] Password:  
266-[2024-04-15 10:05:29.645645 +0800][Dump   ][Utility           ] Host Name: node2.cern.ch
267-[2024-04-15 10:05:29.645645 +0800][Dump   ][Utility           ] Port:      1095
268-[2024-04-15 10:05:29.645645 +0800][Dump   ][Utility           ] Path:      
269-[2024-04-15 10:05:29.645651 +0800][Debug  ][PostMaster        ] Creating new channel to: root://node2.cern.ch:1095/
270-[2024-04-15 10:05:29.645821 +0800][Debug  ][PostMaster        ] [node2.cern.ch:1095] Stream parameters: Network Stack: IPAuto, Connection Window: 120, ConnectionRetry: 5, Stream Error Window: 1800
271-[2024-04-15 10:05:29.645834 +0800][Debug  ][TaskMgr           ] Registering task: "TickGeneratorTask for: root://node2.cern.ch:1095/" to be run at: [2024-04-15 10:05:44 +0800]
272-[2024-04-15 10:05:29.645839 +0800][Dump   ][PostMaster        ] [node2.cern.ch:1095] Sending message kXR_open (file: /eos/dev/testfile?cap.msg=iarIobHpITHH7mFmxoX7idszB2zfDKtifzPB6K+R6JS+RKsPlhvP/kBx+Mm93VS8+qRlKzLiXzUF/VOwqQcYSDU/uH5hzoLQKAX4Zd/hRLLkV/7Fyb+9LDxNOihyfV+URFtR+VNMifzrlpu949i7QOFICsR/vzPNRCJlaIgc3xxrTX0rhIt6PK54CIBAFXxrWUnDq35SUML2j4qcT/bsmU6FyyVCFFVI3uENk3VKbpFr2LzhkhS1QfYF94ahXeL1OpQP7Of2kLd3V05o1fD/PpnA2S/RXpJqLmU10p0GF+itM8hT50AYelRG0rJddDNBDihMhH+OmjzT+9LU1HFOcZ6/SYG9PRSuIb9d2saOEO3+6o3md+itMBdMhoilxgsxK9ZyIH11/iw=&cap.sym=pTJWNr6GA/LZgn7M4/uGj4P/haA=&eos.clientinfo=zbase64:MDAwMDAwNjF4nBXIUQqAIBBF0a20ArGiIGEWk/oGhRhlUqLdl3/n3lIhThtZs69TLs4/lIWH7pAQyQ62t4J8Z4YijlE1F4rgs19t9L+zIjSSErGYABUTkpvtsX2BAyH1&mgm.id=00000073&mgm.logid=9ff2786a-facc-11ee-adf8-f46b8c0b1144&mgm.replicahead=0&mgm.replicaindex=0&oss.asize=46, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) (0x1227fa0) through substream 0 expecting answer at 0
273-[2024-04-15 10:05:29.645870 +0800][Debug  ][PostMaster        ] [node2.cern.ch:1095] Found 1 address(es): [::ffff:51.10.64.183]:1095
274-[2024-04-15 10:05:29.645882 +0800][Debug  ][AsyncSock         ] [node2.cern.ch:1095.0] Attempting connection to [::ffff:51.10.64.183]:1095
275-[2024-04-15 10:05:29.645900 +0800][Debug  ][Poller            ] Adding socket 0xfc009d50 to the poller
276-[2024-04-15 10:05:29.645974 +0800][Debug  ][AsyncSock         ] [node2.cern.ch:1095.0] Async connection call returned
277-[2024-04-15 10:05:29.645996 +0800][Debug  ][XRootDTransport   ] [node2.cern.ch:1095.0] Sending out the initial hand shake + kXR_protocol
278-[2024-04-15 10:05:29.646013 +0800][Dump   ][AsyncSock         ] [node2.cern.ch:1095.0] Wrote a message:  (0x1380), 44 bytes
279-[2024-04-15 10:05:29.646134 +0800][Dump   ][XRootDTransport   ] [msg: 0x1660] Expecting 8 bytes of message body
280-[2024-04-15 10:05:29.646138 +0800][Dump   ][AsyncSock         ] [node2.cern.ch:1095.0] Received message header, size: 8
281-[2024-04-15 10:05:29.646141 +0800][Dump   ][AsyncSock         ] [node2.cern.ch:1095.0] Received a message of 16 bytes
282-[2024-04-15 10:05:29.646145 +0800][Debug  ][XRootDTransport   ] [node2.cern.ch:1095.0] Got the server hand shake response (type: server [], protocol version 511)
283-[2024-04-15 10:05:29.646149 +0800][Dump   ][XRootDTransport   ] [msg: 0x1660] Expecting 8 bytes of message body
284-[2024-04-15 10:05:29.646152 +0800][Dump   ][AsyncSock         ] [node2.cern.ch:1095.0] Received message header, size: 8
285-[2024-04-15 10:05:29.646155 +0800][Dump   ][AsyncSock         ] [node2.cern.ch:1095.0] Received a message of 16 bytes
286-[2024-04-15 10:05:29.646158 +0800][Debug  ][XRootDTransport   ] [node2.cern.ch:1095.0] kXR_protocol successful (type: server [], protocol version 511)
287-[2024-04-15 10:05:29.646197 +0800][Debug  ][XRootDTransport   ] [node2.cern.ch:1095.0] Sending out kXR_login request, username: root, cgi: xrd.cc=ch&xrd.tz=8&xrd.appname=xrdcp&xrd.info=&xrd.hostname=node3.cern.ch&xrd.rn=5.6.9, dual-stack: false, private IPv4: false, private IPv6: false
288-[2024-04-15 10:05:29.646206 +0800][Dump   ][AsyncSock         ] [node2.cern.ch:1095.0] Wrote a message:  (0x1810), 110 bytes
289-[2024-04-15 10:05:29.646317 +0800][Dump   ][XRootDTransport   ] [msg: 0x1380] Expecting 51 bytes of message body
290-[2024-04-15 10:05:29.646324 +0800][Dump   ][AsyncSock         ] [node2.cern.ch:1095.0] Received message header, size: 8
291-[2024-04-15 10:05:29.646328 +0800][Dump   ][AsyncSock         ] [node2.cern.ch:1095.0] Received a message of 59 bytes
292-[2024-04-15 10:05:29.646332 +0800][Debug  ][XRootDTransport   ] [node2.cern.ch:1095.0] Logged in, session: 060000001c0f00002500000006000000
293-[2024-04-15 10:05:29.646335 +0800][Debug  ][XRootDTransport   ] [node2.cern.ch:1095.0] Authentication is required: &P=unix&P=sss,0.+13:/etc/eos.keytab
294-[2024-04-15 10:05:29.646337 +0800][Debug  ][XRootDTransport   ] [node2.cern.ch:1095.0] Sending authentication data
295-[2024-04-15 10:05:29.646430 +0800][Debug  ][XRootDTransport   ] [node2.cern.ch:1095.0] Trying to authenticate using unix
296-[2024-04-15 10:05:29.646482 +0800][Dump   ][AsyncSock         ] [node2.cern.ch:1095.0] Wrote a message:  (0x1660), 39 bytes
297-[2024-04-15 10:05:29.646548 +0800][Dump   ][XRootDTransport   ] [msg: 0x1810] Expecting 0 bytes of message body
298-[2024-04-15 10:05:29.646552 +0800][Dump   ][AsyncSock         ] [node2.cern.ch:1095.0] Received message header, size: 8
299-[2024-04-15 10:05:29.646555 +0800][Dump   ][AsyncSock         ] [node2.cern.ch:1095.0] Received a message of 8 bytes
300-[2024-04-15 10:05:29.646559 +0800][Debug  ][XRootDTransport   ] [node2.cern.ch:1095.0] Authenticated with unix.
301-[2024-04-15 10:05:29.646563 +0800][Debug  ][PostMaster        ] [node2.cern.ch:1095] Stream 0 connected (IPv4).
302-[2024-04-15 10:05:29.646570 +0800][Dump   ][AsyncSock         ] [node2.cern.ch:1095.0] Wrote a message: kXR_open (file: /eos/dev/testfile?cap.msg=iarIobHpITHH7mFmxoX7idszB2zfDKtifzPB6K+R6JS+RKsPlhvP/kBx+Mm93VS8+qRlKzLiXzUF/VOwqQcYSDU/uH5hzoLQKAX4Zd/hRLLkV/7Fyb+9LDxNOihyfV+URFtR+VNMifzrlpu949i7QOFICsR/vzPNRCJlaIgc3xxrTX0rhIt6PK54CIBAFXxrWUnDq35SUML2j4qcT/bsmU6FyyVCFFVI3uENk3VKbpFr2LzhkhS1QfYF94ahXeL1OpQP7Of2kLd3V05o1fD/PpnA2S/RXpJqLmU10p0GF+itM8hT50AYelRG0rJddDNBDihMhH+OmjzT+9LU1HFOcZ6/SYG9PRSuIb9d2saOEO3+6o3md+itMBdMhoilxgsxK9ZyIH11/iw=&cap.sym=pTJWNr6GA/LZgn7M4/uGj4P/haA=&eos.clientinfo=zbase64:MDAwMDAwNjF4nBXIUQqAIBBF0a20ArGiIGEWk/oGhRhlUqLdl3/n3lIhThtZs69TLs4/lIWH7pAQyQ62t4J8Z4YijlE1F4rgs19t9L+zIjSSErGYABUTkpvtsX2BAyH1&mgm.id=00000073&mgm.logid=9ff2786a-facc-11ee-adf8-f46b8c0b1144&mgm.replicahead=0&mgm.replicaindex=0&oss.asize=46, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) (0x1227fa0), 748 bytes
303-[2024-04-15 10:05:29.646581 +0800][Dump   ][AsyncSock         ] [node2.cern.ch:1095.0] Successfully sent message: kXR_open (file: /eos/dev/testfile?cap.msg=iarIobHpITHH7mFmxoX7idszB2zfDKtifzPB6K+R6JS+RKsPlhvP/kBx+Mm93VS8+qRlKzLiXzUF/VOwqQcYSDU/uH5hzoLQKAX4Zd/hRLLkV/7Fyb+9LDxNOihyfV+URFtR+VNMifzrlpu949i7QOFICsR/vzPNRCJlaIgc3xxrTX0rhIt6PK54CIBAFXxrWUnDq35SUML2j4qcT/bsmU6FyyVCFFVI3uENk3VKbpFr2LzhkhS1QfYF94ahXeL1OpQP7Of2kLd3V05o1fD/PpnA2S/RXpJqLmU10p0GF+itM8hT50AYelRG0rJddDNBDihMhH+OmjzT+9LU1HFOcZ6/SYG9PRSuIb9d2saOEO3+6o3md+itMBdMhoilxgsxK9ZyIH11/iw=&cap.sym=pTJWNr6GA/LZgn7M4/uGj4P/haA=&eos.clientinfo=zbase64:MDAwMDAwNjF4nBXIUQqAIBBF0a20ArGiIGEWk/oGhRhlUqLdl3/n3lIhThtZs69TLs4/lIWH7pAQyQ62t4J8Z4YijlE1F4rgs19t9L+zIjSSErGYABUTkpvtsX2BAyH1&mgm.id=00000073&mgm.logid=9ff2786a-facc-11ee-adf8-f46b8c0b1144&mgm.replicahead=0&mgm.replicaindex=0&oss.asize=46, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) (0x1227fa0).
304-[2024-04-15 10:05:29.646585 +0800][Dump   ][XRootD            ] [node2.cern.ch:1095] Message kXR_open (file: /eos/dev/testfile?cap.msg=iarIobHpITHH7mFmxoX7idszB2zfDKtifzPB6K+R6JS+RKsPlhvP/kBx+Mm93VS8+qRlKzLiXzUF/VOwqQcYSDU/uH5hzoLQKAX4Zd/hRLLkV/7Fyb+9LDxNOihyfV+URFtR+VNMifzrlpu949i7QOFICsR/vzPNRCJlaIgc3xxrTX0rhIt6PK54CIBAFXxrWUnDq35SUML2j4qcT/bsmU6FyyVCFFVI3uENk3VKbpFr2LzhkhS1QfYF94ahXeL1OpQP7Of2kLd3V05o1fD/PpnA2S/RXpJqLmU10p0GF+itM8hT50AYelRG0rJddDNBDihMhH+OmjzT+9LU1HFOcZ6/SYG9PRSuIb9d2saOEO3+6o3md+itMBdMhoilxgsxK9ZyIH11/iw=&cap.sym=pTJWNr6GA/LZgn7M4/uGj4P/haA=&eos.clientinfo=zbase64:MDAwMDAwNjF4nBXIUQqAIBBF0a20ArGiIGEWk/oGhRhlUqLdl3/n3lIhThtZs69TLs4/lIWH7pAQyQ62t4J8Z4YijlE1F4rgs19t9L+zIjSSErGYABUTkpvtsX2BAyH1&mgm.id=00000073&mgm.logid=9ff2786a-facc-11ee-adf8-f46b8c0b1144&mgm.replicahead=0&mgm.replicaindex=0&oss.asize=46, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) has been successfully sent.
305-[2024-04-15 10:05:29.646588 +0800][Debug  ][ExDbgMsg          ] [node2.cern.ch:1095] Moving MsgHandler: 0x121b820 (message: kXR_open (file: /eos/dev/testfile?cap.msg=iarIobHpITHH7mFmxoX7idszB2zfDKtifzPB6K+R6JS+RKsPlhvP/kBx+Mm93VS8+qRlKzLiXzUF/VOwqQcYSDU/uH5hzoLQKAX4Zd/hRLLkV/7Fyb+9LDxNOihyfV+URFtR+VNMifzrlpu949i7QOFICsR/vzPNRCJlaIgc3xxrTX0rhIt6PK54CIBAFXxrWUnDq35SUML2j4qcT/bsmU6FyyVCFFVI3uENk3VKbpFr2LzhkhS1QfYF94ahXeL1OpQP7Of2kLd3V05o1fD/PpnA2S/RXpJqLmU10p0GF+itM8hT50AYelRG0rJddDNBDihMhH+OmjzT+9LU1HFOcZ6/SYG9PRSuIb9d2saOEO3+6o3md+itMBdMhoilxgsxK9ZyIH11/iw=&cap.sym=pTJWNr6GA/LZgn7M4/uGj4P/haA=&eos.clientinfo=zbase64:MDAwMDAwNjF4nBXIUQqAIBBF0a20ArGiIGEWk/oGhRhlUqLdl3/n3lIhThtZs69TLs4/lIWH7pAQyQ62t4J8Z4YijlE1F4rgs19t9L+zIjSSErGYABUTkpvtsX2BAyH1&mgm.id=00000073&mgm.logid=9ff2786a-facc-11ee-adf8-f46b8c0b1144&mgm.replicahead=0&mgm.replicaindex=0&oss.asize=46, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) ) from out-queue to in-queue.
306-[2024-04-15 10:05:29.646591 +0800][Dump   ][PostMaster        ] [node2.cern.ch:1095.0] All messages consumed, disable uplink
307-[2024-04-15 10:05:29.646714 +0800][Dump   ][XRootDTransport   ] [msg: 0x2100] Expecting 74 bytes of message body
308-[2024-04-15 10:05:29.646718 +0800][Dump   ][AsyncSock         ] [node2.cern.ch:1095.0] Received message header for 0x2100 size: 8
309-[2024-04-15 10:05:29.646721 +0800][Debug  ][ExDbgMsg          ] [msg: 0x2100] Assigned MsgHandler: 0x121b820.
310-[2024-04-15 10:05:29.646723 +0800][Debug  ][ExDbgMsg          ] [handler: 0x121b820] Removed MsgHandler: 0x121b820 from the in-queue.
311-[2024-04-15 10:05:29.646729 +0800][Dump   ][AsyncSock         ] [node2.cern.ch:1095.0] Received message 0x2100 of 82 bytes
312-[2024-04-15 10:05:29.646732 +0800][Dump   ][PostMaster        ] [node2.cern.ch:1095] Handling received message: 0x2100.
313-[2024-04-15 10:05:29.646744 +0800][Dump   ][XRootD            ] [node2.cern.ch:1095] Got kXR_wait response of 10 seconds to message kXR_open (file: /eos/dev/testfile?cap.msg=iarIobHpITHH7mFmxoX7idszB2zfDKtifzPB6K+R6JS+RKsPlhvP/kBx+Mm93VS8+qRlKzLiXzUF/VOwqQcYSDU/uH5hzoLQKAX4Zd/hRLLkV/7Fyb+9LDxNOihyfV+URFtR+VNMifzrlpu949i7QOFICsR/vzPNRCJlaIgc3xxrTX0rhIt6PK54CIBAFXxrWUnDq35SUML2j4qcT/bsmU6FyyVCFFVI3uENk3VKbpFr2LzhkhS1QfYF94ahXeL1OpQP7Of2kLd3V05o1fD/PpnA2S/RXpJqLmU10p0GF+itM8hT50AYelRG0rJddDNBDihMhH+OmjzT+9LU1HFOcZ6/SYG9PRSuIb9d2saOEO3+6o3md+itMBdMhoilxgsxK9ZyIH11/iw=&cap.sym=pTJWNr6GA/LZgn7M4/uGj4P/haA=&eos.clientinfo=zbase64:MDAwMDAwNjF4nBXIUQqAIBBF0a20ArGiIGEWk/oGhRhlUqLdl3/n3lIhThtZs69TLs4/lIWH7pAQyQ62t4J8Z4YijlE1F4rgs19t9L+zIjSSErGYABUTkpvtsX2BAyH1&mgm.id=00000073&mgm.logid=9ff2786a-facc-11ee-adf8-f46b8c0b1144&mgm.replicahead=0&mgm.replicaindex=0&oss.asize=46, mode: 0644, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ): FST still misses the required capability key; come back in 10 seconds!
314-[2024-04-15 10:05:29.646756 +0800][Debug  ][ExDbgMsg          ] [node2.cern.ch:1095] Scheduling WaitTask for MsgHandler: 0x121b820 (message: kXR_open (file: /eos/dev/testfile?cap.msg=iarIobHpITHH7mFmxoX7idszB2zfDKtifzPB6K+R6JS+RKsPlhvP/kBx+Mm93VS8+qRlKzLiXzUF/VOwqQcYSDU/uH5hzoLQKAX4Zd/hRLLkV/7Fyb+9LDxNOihyfV+URFtR+VNMifzrlpu949i7QOFICsR/vzPNRCJlaIgc3xxrTX0rhIt6PK54CIBAFXxrWUnDq35SUML2j4qcT/bsmU6FyyVCFFVI3uENk3VKbpFr2LzhkhS1QfYF94ahXeL1OpQP7Of2kLd3V05o1fD/PpnA2S/RXpJqLmU10p0GF+itM8hT50AYelRG0rJddDNBDihMhH+OmjzT+9LU1HFOcZ6/SYG9PRSuIb9d2saOEO3+6o3md+itMBdMhoilxgsxK9ZyIH11/iw=&cap.sym=pTJWNr6GA/LZgn7M4/uGj4P/haA=&eos.clientinfo=zbase64:MDAwMDAwNjF4nBXIUQqAIBBF0a20ArGiIGEWk/oGhRhlUqLdl3/n3lIhThtZs69TLs4/lIWH7pAQyQ62t4J8Z4YijlE1F4rgs19t9L+zIjSSErGYABUTkpvtsX2BAyH1&mgm.id=00000073&mgm.logid=9ff2786a-facc-11ee-adf8-f46b8c0b1144&mgm.replicahead=0&mgm.replicaindex=0&oss.asize=46, mode: 0444, flags: kXR_new kXR_open_updt kXR_async kXR_retstat ) ).
315-[2024-04-15 10:05:29.646763 +0800][Debug  ][TaskMgr           ] Registering task: "WaitTask for: 0x0x1227fa0" to be run at: [2024-04-15 10:05:39 +0800]
316-[2024-04-15 10:05:30.638732 +0800][Dump   ][TaskMgr           ] Running task: "FileTimer task"
[root@node3 ~]#

We also get a lot of FST still misses the required capability key errors in the fst logs.
It seems the file is sent successfully via xroot tool, but I get error responses from eos server.
Let me kown if you need more info or hava any new ideas.

Best,
Sarric

CERN Accelerating science

Mgm Error: Failed to load key from Configstore