scitokens_GenerateAcls: ACL generation from SciToken failed: Timeout was reached

Dear All!
I’m running EOS 5.1.14 on my testbed cluster.
I encountered a problem with authorization when using scitokens.

I try to use token through curl or gfal utility and get error: 403 token authorization failed and in log’s mgm: scitokens_Access: Token not found in recent cache; parsing.

Below is some possibly useful information about my cluster and the settings it uses:

Curl
curl -k -v -L  -X PUT -H  "Authorization: Bearer $(cat /tmp/bt_u111)" --upload-file file https://vm-eos.jinr.ru:8443/eos/user/t/telecast/file_111

* About to connect() to vm-eos.jinr.ru port 8443 (#0)
*   Trying 159.93.221.220...
* Connected to vm-eos.jinr.ru (159.93.221.220) port 8443 (#0)
* Initializing NSS with certpath: sql:/etc/pki/nssdb
* skipping SSL peer certificate verification
* NSS: client certificate not found (nickname not specified)
* SSL connection using TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
* Server certificate:
*       subject: CN=vm-eos.jinr.ru,OU=jinr.ru,OU=hosts,O=RDIG,C=RU
*       start date: Feb 27 15:45:42 2023 GMT
*       expire date: Mar 29 15:45:42 2024 GMT
*       common name: vm-eos.jinr.ru
*       issuer: CN=Russian Data-Intensive Grid CA,O=RDIG,C=RU
> PUT /eos/user/t/telecast/file_111 HTTP/1.1
> User-Agent: curl/7.29.0
> Host: vm-eos.jinr.ru:8443
> Accept: */*

> Authorization: Bearer eyJraWQiOiJyc2ExIiwiYWxnIjoiUlMyNTYifQ.eyJ3bGNnLnZlciI6IjEuMCIsInN1YiI6IjhhNjBjODFmLTY2YmMtNDk3NC04NmQ3LTI0OGZmZGQ0OGM0NCIsImF1ZCI6Imh0dHBzOlwvXC93bGNnLmNlcm4uY2hcL2p3dFwvdjFcL2FueSIsIm5iZiI6MTY4MjQyMTMyMCwic2NvcGUiOiJhZGRyZXNzIHN0b3JhZ2UuY3JlYXRlOlwvIHBob25lIG9wZW5pZCBvZmZsaW5lX2FjY2VzcyBwcm9maWxlIHN0b3JhZ2UucmVhZDpcLyBlZHVwZXJzb25fc2NvcGVkX2FmZmlsaWF0aW9uIGVkdXBlcnNvbl9lbnRpdGxlbWVudCBlbWFpbCB3bGNnIHdsY2cuZ3JvdXBzIiwiaXNzIjoiaHR0cHM6XC9cL3ZtMjIxLTIyMS5qaW5yLnJ1IiwiZXhwIjoxNjgyNDI0OTIwLCJpYXQiOjE2ODI0MjEzMjAsImp0aSI6ImIwMWRkN2QzLTkzMGYtNDQzNS1hMzNiLTllMTliZjJlNGQwNSIsImNsaWVudF9pZCI6IjIwNTgyNjBhLWI3MDktNDU3Ni05OTlhLTA1ODQ5Y2Y0N2ExNyIsIndsY2cuZ3JvdXBzIjpbIlwvZW9zIiwiXC9qdW5vIl19.pCKzaMqFahrt34B-UecgV6KPEbEfR3suWjarubk59-3Xt7PTHPwoNULGnPykwhS8z9O_0SdyLw2J_U8C2Za2fzHO9yAlCje5lBukRs3iJwuQN0SPjWMEjsD5SyHovS4wCR2KbzA6o2Z3y2G9o6Ur1NldWvVE8nKvPxu4ASAlui0                                                                
> Content-Length: 24
> Expect: 100-continue
>
* Done waiting for 100-continue
* We are completely uploaded and fine
< HTTP/1.1 403 token authorization failed
< Connection: Keep-Alive
< Server: XrootD/1.1.1
< Content-Length: 26
<
gfal
export BEARER_TOKEN=$(cat /tmp/bt_u111)
gfal-copy /tmp/testfile.1GB https://vm-eos.jinr.ru:8443/eos/user/t/telecast/testfile.1GB
Copying file:///tmp/testfile.1GB   [FAILED]  after 8s
gfal-copy error: 1 (Operation not permitted) - DESTINATION OVERWRITE   HTTP 403 : Permission refused
Explore token
echo $(echo -n $BEARER_TOKEN) | cut -d. -f2 | base64 --decode | jq .
{
  "wlcg.ver": "1.0",
  "sub": "8a60c81f-66bc-4974-86d7-248ffdd48c44",
  "aud": "https://wlcg.cern.ch/jwt/v1/any",
  "nbf": 1682424955,
  "scope": "address storage.create:/ phone openid offline_access profile storage.read:/ eduperson_scoped_affiliation eduperson_entitlement email wlcg wlcg.groups",                                                                         
  "iss": "https://vm221-221.jinr.ru",
  "exp": 1682428555,
  "iat": 1682424955,
  "jti": "ffc829cf-ef5e-4a35-87f9-01b666dc1d7b",
  "client_id": "2058260a-b709-4576-999a-05849cf47a17",
  "wlcg.groups": [
    "/eos",
    "/juno"
  ]
}

My cluster consists from 3 VM:
VM1:mgm,sync,qdb,mq,fst
VM2:mgm,sync,qdb,mq,fst
VM3:fst,qdb

xrd.cf.mgm

cat /etc/xrd.cf.mgm | grep -Ev "^#|^[[:space:]]$

XrdSecDEBUG=6
xrootd.fslib libXrdEosMgm.so
xrootd.seclib libXrdSec.so
xrootd.async off nosf
xrootd.chksum adler32
xrd.sched mint 16 maxt 256 idle 300
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.protocol krb5 /etc/krb5.keytab host/vm1-eos-mgm1.jinr.ru@JINR.RU
sec.protbind localhost.localdomain unix sss
sec.protbind localhost unix sss
sec.protbind * only krb5 sss unix
mgmofs.fs /
mgmofs.targetport 1095
mgmofs.trace all debug
mgmofs.broker root://vm-eos.jinr.ru:1097//eos/
mgmofs.instance eosdev
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.cfgtype quarkdb
mgmofs.alias vm-eos.jinr.ru
mgmofs.fstgw vm1-eos-mgm1.jinr.ru:3001
mgmofs.nslib /usr/lib64/libEosNsQuarkdb.so
mgmofs.qdbcluster vm1-eos-db1.jinr.ru:7777 vm2-eos-db2.jinr.ru:7777 vm3-eos-db3.jinr.ru:7777
mgmofs.qdbpassword_file /etc/xrootd/eos.keytab
mgmofs.centraldrain true

xrd.protocol XrdHttp:8443 /usr/lib64/libXrdHttp.so
http.cadir /etc/grid-security/certificates/
http.cert /etc/grid-security/daemon/hostcert.pem
http.key /etc/grid-security/daemon/hostkey.pem
http.gridmap /etc/grid-security/grid-mapfile
http.secxtractor libXrdVoms.so
http.exthandler xrdtpc /usr/lib64/libXrdHttpTPC.so
http.exthandler EosMgmHttp /usr/lib64/libEosMgmHttp.so eos::mgm::http::redirect-to-https=0
mgmofs.macaroonslib /usr/lib64/libXrdMacaroons.so /usr/lib64/libXrdAccSciTokens.so
scitokens.trace all
macaroons.secretkey /etc/eos.macaroon.secret
all.sitename vm-eos
ofs.tpc redirect delegated vm-eos.jinr.ru:1094

xrd.cf.fst

set MGM=$EOS_MGM_ALIAS

xrootd.fslib -2 libXrdEosFst.so
xrootd.async off nosf
xrd.network keepalive
xrootd.redirect $(MGM):1094 chksum

xrootd.seclib libXrdSec.so
sec.protocol unix
sec.protocol sss -c /etc/eos.client.keytab -s /etc/eos.client.keytab
sec.protbind * only unix sss
all.export / nolock
all.trace none
all.manager localhost 2131
xrd.port 1095
ofs.persist off
ofs.osslib libEosFstOss.so
ofs.tpc pgm /opt/eos/xrootd/bin/xrdcp
fstofs.broker root://localhost:1097//eos/
fstofs.autoboot true
fstofs.quotainterval 10
fstofs.metalog /var/eos/md/
fstofs.qdbcluster vm1-eos-db1.jinr.ru:7777 vm2-eos-db2.jinr.ru:7777 vm3-eos-db3.jinr.ru:7777
fstofs.qdbpassword_file /etc/eos.keytab-qdb

xrd.tls /etc/grid-security/daemon/hostcert.pem /etc/grid-security/daemon/hostkey.pem
xrd.tlsca certdir /etc/grid-security/certificates/
xrd.protocol XrdHttp:8444 libXrdHttp.so
http.exthandler EosFstHttp /usr/lib64/libEosFstHttp.so none
http.exthandler xrdtpc libXrdHttpTPC.so
http.trace all

MGM logs
uid=99 gid=99 name=- geo="" verb=PUT path=/eos/user/t/telecast/file_111
230425 15:40:43 time=1682426443.108893 func=MatchesPath              level=INFO  logid=static.............................. unit=mgm@vm1-eos-mgm1.jinr.ru:1094 tid=00007f5baf336700 source=EosMgmHttpHandler:219          tident= sec=(null) 
uid=99 gid=99 name=- geo="" verb=PUT path=/eos/user/t/telecast/file_111
230425 15:40:43 time=1682426443.108976 func=ProcessReq               level=INFO  logid=static.............................. unit=mgm@vm1-eos-mgm1.jinr.ru:1094 tid=00007f5baf336700 source=EosMgmHttpHandler:283          tident= sec=(null) 
uid=99 gid=99 name=- geo="" msg="normalize hdr" key="Accept" value="*/*"
230425 15:40:43 time=1682426443.109012 func=ProcessReq               level=INFO  logid=static.............................. unit=mgm@vm1-eos-mgm1.jinr.ru:1094 tid=00007f5baf336700 source=EosMgmHttpHandler:283          tident= sec=(null) 
uid=99 gid=99 name=- geo="" msg="normalize hdr" key="Authorization" value="Bearer eyJraWQiOiJyc2ExIiwiYWxnIjoiUlMyNTYifQ.eyJ3bGNnLnZlciI6IjEuMCIsInN1YiI6IjhhNjBjODFmLTY2YmMtNDk3NC04NmQ3LTI0OGZmZGQ0OGM0NCIsImF1ZCI6Imh0dHBzOlwvXC93bGNnLmNl
cm4uY2hcL2p3dFwvdjFcL2FueSIsIm5iZiI6MTY4MjQyNDk1NSwic2NvcGUiOiJhZGRyZXNzIHN0b3JhZ2UuY3JlYXRlOlwvIHBob25lIG9wZW5pZCBvZmZsaW5lX2FjY2VzcyBwcm9maWxlIHN0b3JhZ2UucmVhZDpcLyBlZHVwZXJzb25fc2NvcGVkX2FmZmlsaWF0aW9uIGVkdXBlcnNvbl9lbnRpdGxlbWVudCBlb
WFpbCB3bGNnIHdsY2cuZ3JvdXBzIiwiaXNzIjoiaHR0cHM6XC9cL3ZtMjIxLTIyMS5qaW5yLnJ1IiwiZXhwIjoxNjgyNDI4NTU1LCJpYXQiOjE2ODI0MjQ5NTUsImp0aSI6ImZmYzgyOWNmLWVmNWUtNGEzNS04N2Y5LTAxYjY2NmRjMWQ3YiIsImNsaWVudF9pZCI6IjIwNTgyNjBhLWI3MDktNDU3Ni05OTlhLTA1OD
Q5Y2Y0N2ExNyIsIndsY2cuZ3JvdXBzIjpbIlwvZW9zIiwiXC9qdW5vIl19.QN46DxDPb8GRpuOxZQ7wHBgJZfvnSxPc79EaVpYxwU6Eb_SV3lVccp7letUxS3DqrykMoVPp9qKGpLbm1yRgnewsMvj3PtHxUuCoQ91TnNuooYpkJ-NRdgqFeFHB7CwZloeRqDAu8i9ax37yFyWeg9K-5jW1tbBmnhYAfwoEPYo"
230425 15:40:43 time=1682426443.109033 func=ProcessReq               level=INFO  logid=static.............................. unit=mgm@vm1-eos-mgm1.jinr.ru:1094 tid=00007f5baf336700 source=EosMgmHttpHandler:283          tident= sec=(null) 
uid=99 gid=99 name=- geo="" msg="normalize hdr" key="Content-Length" value="24"
230425 15:40:43 time=1682426443.109066 func=ProcessReq               level=INFO  logid=static.............................. unit=mgm@vm1-eos-mgm1.jinr.ru:1094 tid=00007f5baf336700 source=EosMgmHttpHandler:283          tident= sec=(null) 
uid=99 gid=99 name=- geo="" msg="normalize hdr" key="Expect" value="100-continue"
230425 15:40:43 time=1682426443.109078 func=ProcessReq               level=INFO  logid=static.............................. unit=mgm@vm1-eos-mgm1.jinr.ru:1094 tid=00007f5baf336700 source=EosMgmHttpHandler:283          tident= sec=(null) 
uid=99 gid=99 name=- geo="" msg="normalize hdr" key="Host" value="vm-eos.jinr.ru:8443"
230425 15:40:43 time=1682426443.109145 func=ProcessReq               level=INFO  logid=static.............................. unit=mgm@vm1-eos-mgm1.jinr.ru:1094 tid=00007f5baf336700 source=EosMgmHttpHandler:283          tident= sec=(null) 
uid=99 gid=99 name=- geo="" msg="normalize hdr" key="User-Agent" value="curl/7.29.0"
230425 15:40:43 time=1682426443.109158 func=ProcessReq               level=INFO  logid=static.............................. unit=mgm@vm1-eos-mgm1.jinr.ru:1094 tid=00007f5baf336700 source=EosMgmHttpHandler:283          tident= sec=(null) 
uid=99 gid=99 name=- geo="" msg="normalize hdr" key="xrd-http-fullresource" value="/eos/user/t/telecast/file_111"
230425 15:40:43 time=1682426443.109170 func=ProcessReq               level=INFO  logid=static.............................. unit=mgm@vm1-eos-mgm1.jinr.ru:1094 tid=00007f5baf336700 source=EosMgmHttpHandler:283          tident= sec=(null) 
uid=99 gid=99 name=- geo="" msg="normalize hdr" key="xrd-http-prot" value="https"
230425 15:40:43 time=1682426443.109181 func=ProcessReq               level=INFO  logid=static.............................. unit=mgm@vm1-eos-mgm1.jinr.ru:1094 tid=00007f5baf336700 source=EosMgmHttpHandler:283          tident= sec=(null) 
uid=99 gid=99 name=- geo="" msg="normalize hdr" key="xrd-http-query" value=""
230425 15:40:43 10419 scitokens_Access: Trying token-based access control
230425 15:40:43 10419 scitokens_Reconfig: Parsing configuration file: /etc/xrootd/scitokens.cfg
230425 15:40:43 10419 scitokens_Reconfig: Configuring issuer https://vm221-221.jinr.ru
230425 15:40:43 10419 scitokens_Reconfig: Successfully parsed SciTokens mapfile: /etc/xrootd/mapfile
230425 15:40:43 10419 scitokens_Access: Token not found in recent cache; parsing.
...
30425 15:40:49 time=1682426449.548266 func=Schedule2Balance         level=INFO  logid=FstOfsStorage unit=mgm@vm1-eos-mgm1.jinr.ru:1094 tid=00007f5baf738700 source=Schedule2Balance:346           tident=daemon.31359:387@vm2-eos-mgm2 sec=s
ss   uid=0 gid=0 name=daemon geo="RU::JINR::LITVM" cmd=schedule2balance fsid=6 freebytes=43698315264 logid=FstOfsStorage
230425 15:40:49 10418 XrootdXeq: root.389459:439@vm223-1 disc 0:00:00
230425 15:40:49 10419 scitokens_GenerateAcls: ACL generation from SciToken failed: Timeout was reached
230425 15:40:49 10419 scitokens_Access: Failed to generate ACLs for token
230425 15:40:49 time=1682426449.889428 func=ProcessReq               level=ERROR logid=static.............................. unit=mgm@vm1-eos-mgm1.jinr.ru:1094 tid=00007f5baf336700 source=EosMgmHttpHandler:315          tident= sec=(null) uid=99 gid=99 name=- geo="" msg="(token) authorization failed" path="/eos/user/t/telecast/file_111"
230425 15:40:50 time=1682426450.550358 func=Schedule2Balance         level=INFO  logid=FstOfsStorage unit=mgm@vm1-eos-mgm1.jinr.ru:1094 tid=00007f5baf738700 source=Schedule2Balance:346           tident=daemon.31359:387@vm2-eos-mgm2 sec=sss   uid=0 gid=0 name=daemon geo="RU::JINR::LITVM" cmd=schedule2balance fsid=6 freebytes=43698315264 logid=FstOfsStorage
eos vid ls
geotag:"default" => "RU::JINR::LITVM"
gsi:"<pwd>":gid => root
gsi:"<pwd>":uid => root
hostmatch:"protocol=* pattern=t2*.jinr.ru
https:"<pwd>":gid => root
https:"<pwd>":uid => root
krb5:"<pwd>":gid => root
krb5:"<pwd>":uid => root
publicaccesslevel: => 1024
sss:"<pwd>":gid => root
sss:"<pwd>":uid => root
sss:"daemon":gid => root
sss:"daemon":uid => root
sss:"eos_exporter":gid => root
sss:"eos_exporter":uid => root
sudoer                 => uids(daemon,eos_exporter)
tident:"*@t2*.jinr.ru":gid => root
tident:"*@t2*.jinr.ru":uid => root
tident:"*@vm1-eos-mgm1.jinr.ru":gid => root
tident:"*@vm1-eos-mgm1.jinr.ru":uid => root
tident:"*@vm2-eos-mgm2.jinr.ru":gid => root
tident:"*@vm2-eos-mgm2.jinr.ru":uid => root
tident:"*@vm223-1.jinr.ru":gid => root
tident:"*@vm223-1.jinr.ru":uid => root
tident:"*@vm3-eos-fst0.jinr.ru":gid => root
tident:"*@vm3-eos-fst0.jinr.ru":uid => root
tident:"*@vm4-ui1.jinr.ru":gid => root
tident:"*@vm4-ui1.jinr.ru":uid => root
tokensudo              => always
eos attr ls /eos/user/t/telecast
sys.acl="g:1002:rwcmxq"
sys.eos.btime="1681994080.542939441"
sys.forced.blocksize="4k"
sys.forced.checksum="adler"
sys.forced.layout="replica"
sys.forced.nstripes="2"
sys.forced.space="default"
sys.mask="770"
sys.owner.auth="*"
user.acl="

"

eos acl -l /eos/user/t/telecast

g:telecast:rwcmxq

scitokens.cfg
[Global]
audience = https://wlcg.cern.ch/jwt/v1/any

[Issuer OSG-Connect]
issuer = https://vm221-221.jinr.ru
base_path = /
map_subject = False
default_user = telecast
name_mapfile = /etc/xrootd/mapfile
mapfile

[ {"sub": "8a60c81f-66bc-4974-86d7-248ffdd48c44", "path": "/eos/user/t/telecast", "result": "telecast"} ]

Using version software:

EOS
# rpm -qa | grep eos
eos-xrootd-5.5.7-1.el7.cern.x86_64
eos-grpc-devel-1.41.0-1.el7.x86_64
eos-libmicrohttpd-0.9.38-eos.el7.cern.x86_64
eos-server-5.1.14-1.el7.cern.x86_64
eos-grpc-1.41.0-1.el7.x86_64
eos-folly-deps-2019.11.11.00-1.el7.cern.x86_64
eos-folly-2019.11.11.00-1.el7.cern.x86_64
eos-ns-inspect-5.1.14-1.el7.cern.x86_64
eos-client-5.1.14-1.el7.cern.x86_64
eos-quarkdb-5.1.14-1.el7.cern.x86_64
eos-protobuf3-3.17.3-1.el7.cern.eos.x86_64
Xrootd
# rpm -qa | grep xrootd
xrootd-server-libs-5.5.4-1.el7.x86_64
eos-xrootd-5.5.7-1.el7.cern.x86_64
xrootd-scitokens-5.5.4-1.el7.x86_64
xrootd-client-libs-5.5.4-1.el7.x86_64
xrootd-libs-5.5.4-1.el7.x86_64
xrootd-server-5.5.4-1.el7.x86_64
xrootd-voms-5.5.4-1.el7.x86_64
OS
# cat /etc/*release
NAME="Scientific Linux"
VERSION="7.9 (Nitrogen)"
# uname -a
Linux vm-eos.jinr.ru 3.10.0-1160.88.1.el7.x86_64 #1 SMP Tue Mar 7 08:37:40 CST 2023 x86_64 x86_64 x86_64 GNU/Linux

Any help would be greatly appreciated.
Thanks in advance.

Hi Aleksandr,

Could you double check the version of the scitokens-cpp package that you are using?
You might be hit by this issue that I reported on their tracker:
https://github.com/scitokens/scitokens-cpp/issues/114

Cheers,
Elvin

Hi Elvin,

Yes, you are right, i’m using version scitokens-cpp-1.0.0-1.el7.x86_64
I’ll try make downgrade or build the library myself with modify default timeout for 10 sec.

Thank you for info!