-
Notifications
You must be signed in to change notification settings - Fork 149
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
occasional permission denied with proxy, ztn, multi-user origin #1943
Comments
It appears that the issue really is that the "name" field is being set to
Failure when looking up UID for username
http://cilogon.org/serverA/users/6772316
Which is the token issuer. I really don't know what the name field should
be set to but, clearly, that should not be it. Notice that the name
appears both in the proxy and in the origin. Could you provide a case
where it actually works (proxy and origin) so we can see what the name
field looks like when it works.
On Mon, 6 Mar 2023, Bryan Hess wrote:
Hello, I have what seems to be a race condition writing files through a proxy server. The proxy passes the credentials to the origin, where the the multiuser plugin is used to write the file as a default_user mapped in scitokens.cfg.
If I run the same xrdcp repeatedly, it will work ~90% of the time, occasionally failing with "permission denied" which I assume happens because the origin server does not switch UIDs in that instance(?) I can find no pattern to the failure. When writing directly to the origin, bypassing the proxy, it always succeeds. I suspect something in the config of the proxy, or some race condition on the origin related to sss+ztn and multiuser.
Here are the two configs and examples of log files from both the successful and the failing cases.
Any pointers greatly appreciated.
proxy config (dtn2201):
```
all.export /
ofs.osslib libXrdPss.so
ofs.ckslib * libXrdPss.so
pss.origin roots://scifs2103.jlab.org:1094
pss.persona client strict verify
xrootd.tls all
xrd.tls /etc/grid-security/xrd/hostcert.pem /etc/grid-security/xrd/hostkey.pem
xrd.tlsca certdir /etc/grid-security/certificates
xrootd.seclib default
ofs.authorize
acc.authdb /etc/xrootd/Authfile
acc.authrefresh 60
ofs.authlib libXrdAccSciTokens.so
sec.protocol ztn
sec.protocol sss -k -s /etc/xrootd/p3.keytab -c /etc/xrootd/p3.keytab --getcreds --proxy ztn
all.adminpath /var/spool/xrootd
all.pidpath /var/run/xrootd
sec.trace debug
ofs.trace all
xrootd.trace all
scitokens.trace all debug
ztn.trace all debug
auth.trace all debug
pss.trace all debug
```
origin config (scifs2103):
```
all.export /eic
oss.localroot /xrd
xrd.port 1094
all.role server
xrootd.seclib default
xrootd.tls all
xrd.tls /etc/grid-security/xrd/hostcert.pem /etc/grid-security/xrd/hostkey.pem
xrd.tlsca certdir /etc/grid-security/certificates
ofs.osslib ++ libXrdMultiuser.so
ofs.ckslib ++ libXrdMultiuser.so
ofs.authlib libXrdAccSciTokens.so
#ofs.authlib ++ libXrdAccSciTokens.so
ofs.authorize
acc.authdb /etc/xrootd/Authfile
acc.authrefresh 60
all.manager xrdmgr1 3121
sec.protocol ztn
sec.protocol sss -k -s /etc/xrootd/p3.keytab -c /etc/xrootd/p3.keytab --getcreds --proxy ztn
all.adminpath /var/spool/xrootd
all.pidpath /var/run/xrootd
ofs.trace all debug
oss.trace all debug
auth.trace all debug
scitokens.trace all debug
xrootd.trace all
pss.trace all debug
```
Command line examples, no changes in between:
```
xrdcp -d1 -f /tmp/eic-xrdcp.2vdR2b roots://dtn2201.jlab.org//eic/eic2/transfer/
[2023-03-06 12:49:21.193294 -0500][Info ][AsyncSock ] [dtn2201.jlab.org:1094.0] TLS hand-shake done.
[2023-03-06 12:49:21.285359 -0500][Error ][App ] [ERROR] Error response: permission denied (destination)
[ERROR] Server responded with an error: [3010] Unable to locate /eic/eic2/transfer/; permission denied
xrdcp -d1 -f /tmp/eic-xrdcp.JuRZGk roots://dtn2201.jlab.org//eic/eic2/transfer/
[2023-03-06 12:50:39.081028 -0500][Info ][AsyncSock ] [dtn2201.jlab.org:1094.0] TLS hand-shake done.
[48B/48B][100%][==================================================][48B/s]
```
proxy log for the failing case:
```
230306 12:49:21 2465329 ***@***.*** Xrootd_Protocol: 0000 req=protocol dlen=0
230306 12:49:21 2465329 ***@***.*** Xrootd_Response: 0000 sending 8 data bytes; status=0
230306 12:49:21 2465329 XrdLinkXeq: ***@***.*** connection upgraded to TLSv1.2
230306 12:49:21 2465329 ***@***.*** Xrootd_Protocol: 0000 req=login dlen=93
230306 12:49:21 2465329 sec_getParms: ifarm1801.jlab.org sectoken=&P=ztn,0:4096:&P=sss,0.+013:/etc/xrootd/p3.keytab
230306 12:49:21 2465329 ***@***.*** Xrootd_Response: 0000 sending 65 data bytes; status=0
230306 12:49:21 2465329 ***@***.*** Xrootd_Protocol: 0000 req=auth dlen=910
sec_PM: Using ztn protocol, args='0:4096:'
230306 12:49:21 2465329 ***@***.*** Xrootd_Response: 0000 sending OK
***@***.*** Protocol 'ztn'
***@***.*** Name 'http://cilogon.org/serverA/users/6772316'
***@***.*** Host 'ifarm1801.jlab.org'
***@***.*** Vorg ''
***@***.*** Role ''
***@***.*** Grps ''
***@***.*** Caps ''
***@***.*** Pidn ***@***.***'
***@***.*** Mon ''
***@***.*** Crlen 897
***@***.*** ueid 4
***@***.*** uid 0
***@***.*** gid 0
230306 12:49:21 2465329 XrootdXeq: ***@***.*** pub IPv4 TLSv1.2 login as http://cilogon.org/serverA/users/6772316
230306 12:49:21 2465329 ***@***.*** Xrootd_Protocol: 0100 req=stat dlen=19
230306 12:49:21 2465329 ***@***.*** ofs_stat: fn=/eic/eic2/transfer/
230306 12:49:21 2465329 scitokens_Access: Trying token-based access control
230306 12:49:21 2465329 scitokens_Reconfig: Parsing configuration file: /etc/xrootd/scitokens.cfg
230306 12:49:21 2465329 scitokens_Reconfig: Configuring issuer https://cilogon.org/eic
230306 12:49:21 2465329 scitokens_Access: Token not found in recent cache; parsing.
230306 12:49:21 2465329 scitokens_Access: New valid token mapped_username=, subject=http://cilogon.org/serverA/users/6772316, issuer=https://cilogon.org/eic, authorizations=/eic:read,dir,stat,create,mkdir,mv,insert,update,chmod,del
230306 12:49:21 2465329 scitokens_Access: Grant authorization based on scopes for operation=stat, path=/eic/eic2/transfer/
230306 12:49:21 2465329 ofs_stat: ***@***.*** Unable to locate /eic/eic2/transfer/; permission denied
230306 12:49:21 2465329 ***@***.*** Xrootd_Protocol: 0100 rc=-1 stat /eic/eic2/transfer/
230306 12:49:21 2465329 ***@***.*** Xrootd_Response: 0100 sending err 3010: Unable to locate /eic/eic2/transfer/; permission denied
~> [2023-03-06 12:49:21.287124 -0500][Error ][TlsMsg ]
***@***.*** TLS error rc=0 ec=6 (zero_return) errno=0.
… 230306 12:49:21 2465329 XrootdXeq: ***@***.*** disc 0:00:00
```
origin log for the failing case:
```
230306 12:49:21 3232959 ***@***.*** Xrootd_Protocol: 0000 req=protocol dlen=0
230306 12:49:21 3232959 ***@***.*** Xrootd_Response: 0000 sending 8 data bytes; status=0
230306 12:49:21 3232959 XrdLinkXeq: ***@***.*** connection upgraded to TLSv1.3
230306 12:49:21 3232959 ***@***.*** Xrootd_Protocol: 0000 req=login dlen=92
230306 12:49:21 3232959 ***@***.*** Xrootd_Response: 0000 sending 65 data bytes; status=0
230306 12:49:21 3232959 ***@***.*** Xrootd_Protocol: 0000 req=auth dlen=1171
230306 12:49:21 3232959 ***@***.*** Xrootd_Response: 0000 sending OK
***@***.*** Protocol 'ztn'
***@***.*** Name 'http://cilogon.org/serverA/users/6772316'
***@***.*** Host 'dtn2201.jlab.org'
***@***.*** Vorg ''
***@***.*** Role ''
***@***.*** Grps ''
***@***.*** Caps ''
***@***.*** Pidn ***@***.***'
***@***.*** Mon ''
***@***.*** Crlen 897
***@***.*** ueid 10
***@***.*** uid 0
***@***.*** gid 0
***@***.*** Attr xrd.appname = 'xrdcp'
***@***.*** Attr = ''
230306 12:49:21 3232959 XrootdXeq: ***@***.*** pub IP46 TLSv1.3 login as http://cilogon.org/serverA/users/6772316 via ztn auth for ***@***.***
230306 12:49:21 3232959 multiuser_UserSentry: Failure when looking up UID for username http://cilogon.org/serverA/users/6772316 No such file or directory
230306 12:49:21 3232959 ***@***.*** Xrootd_Protocol: 0100 req=stat dlen=19
230306 12:49:21 3232959 ***@***.*** ofs_stat: fn=/eic/eic2/transfer/
230306 12:49:21 3232959 ofs_stat: ***@***.*** Unable to locate /eic/eic2/transfer/; permission denied
230306 12:49:21 3232959 ***@***.*** Xrootd_Protocol: 0100 rc=-1 stat /eic/eic2/transfer/
230306 12:49:21 3232959 ***@***.*** Xrootd_Response: 0100 sending err 3010: Unable to locate /eic/eic2/transfer/; permission denied
```
proxy log, working case:
```
230306 12:50:39 2465330 ***@***.*** Xrootd_Response: 0000 sending 8 data bytes; status=0
230306 12:50:39 2465330 XrdLinkXeq: ***@***.*** connection upgraded to TLSv1.2
230306 12:50:39 2465330 ***@***.*** Xrootd_Protocol: 0000 req=login dlen=93
230306 12:50:39 2465330 sec_getParms: ifarm1801.jlab.org sectoken=&P=ztn,0:4096:&P=sss,0.+013:/etc/xrootd/p3.keytab
230306 12:50:39 2465330 ***@***.*** Xrootd_Response: 0000 sending 65 data bytes; status=0
230306 12:50:39 2465330 ***@***.*** Xrootd_Protocol: 0000 req=auth dlen=910
sec_PM: Using ztn protocol, args='0:4096:'
230306 12:50:39 2465330 ***@***.*** Xrootd_Response: 0000 sending OK
***@***.*** Protocol 'ztn'
***@***.*** Name 'http://cilogon.org/serverA/users/6772316'
***@***.*** Host 'ifarm1801.jlab.org'
***@***.*** Vorg ''
***@***.*** Role ''
***@***.*** Grps ''
***@***.*** Caps ''
***@***.*** Pidn ***@***.***'
***@***.*** Mon ''
***@***.*** Crlen 897
***@***.*** ueid 5
***@***.*** uid 0
***@***.*** gid 0
230306 12:50:39 2465330 XrootdXeq: ***@***.*** pub IPv4 TLSv1.2 login as http://cilogon.org/serverA/users/6772316
230306 12:50:39 2465330 ***@***.*** Xrootd_Protocol: 0100 req=stat dlen=19
230306 12:50:39 2465330 ***@***.*** ofs_stat: fn=/eic/eic2/transfer/
230306 12:50:39 2465330 scitokens_Access: Trying token-based access control
230306 12:50:39 2465330 scitokens_Reconfig: Parsing configuration file: /etc/xrootd/scitokens.cfg
230306 12:50:39 2465330 scitokens_Reconfig: Configuring issuer https://cilogon.org/eic
230306 12:50:39 2465330 scitokens_Access: Token not found in recent cache; parsing.
230306 12:50:39 2465330 scitokens_Access: New valid token mapped_username=, subject=http://cilogon.org/serverA/users/6772316, issuer=https://cilogon.org/eic, authorizations=/eic:read,dir,stat,create,mkdir,mv,insert,update,chmod,del
230306 12:50:39 2465330 scitokens_Access: Grant authorization based on scopes for operation=stat, path=/eic/eic2/transfer/
230306 12:50:39 2465330 ***@***.*** Xrootd_Protocol: 0100 rc=0 stat /eic/eic2/transfer/
230306 12:50:39 2465330 ***@***.*** Xrootd_Response: 0100 sending 72 data bytes
230306 12:50:39 2465330 ***@***.*** Xrootd_Protocol: 0100 req=open dlen=49
230306 12:50:39 2465330 ***@***.*** Xrootd_Protocol: 0100 open udmat /eic/eic2/transfer//eic-xrdcp.JuRZGk?oss.asize=48
230306 12:50:39 2465330 ***@***.*** ofs_open: 200-40644 fn=/eic/eic2/transfer/eic-xrdcp.JuRZGk
230306 12:50:39 2465330 scitokens_Access: Trying token-based access control
230306 12:50:39 2465330 scitokens_Access: Cached token mapped_username=, subject=http://cilogon.org/serverA/users/6772316, issuer=https://cilogon.org/eic, authorizations=/eic:read,dir,stat,create,mkdir,mv,insert,update,chmod,del
230306 12:50:39 2465330 scitokens_Access: Grant authorization based on scopes for operation=create, path=/eic/eic2/transfer/eic-xrdcp.JuRZGkoss.asize=48
230306 12:50:39 2465330 ***@***.*** ofs_open: 200-40644 fn=/eic/eic2/transfer/eic-xrdcp.JuRZGk
230306 12:50:39 2465330 scitokens_Access: Trying token-based access control
230306 12:50:39 2465330 scitokens_Access: Cached token mapped_username=, subject=http://cilogon.org/serverA/users/6772316, issuer=https://cilogon.org/eic, authorizations=/eic:read,dir,stat,create,mkdir,mv,insert,update,chmod,del
230306 12:50:39 2465330 scitokens_Access: Grant authorization based on scopes for operation=create, path=/eic/eic2/transfer/eic-xrdcp.JuRZGk
230306 12:50:39 2465330 ***@***.*** ofs_fstat: fn=/eic/eic2/transfer/eic-xrdcp.JuRZGk
230306 12:50:39 2465330 ***@***.*** Xrootd_Response: 0100 sending 82 data bytes; status=0
230306 12:50:39 2465330 ***@***.*** Xrootd_Protocol: 0100 req=write dlen=48
230306 12:50:39 2465330 ***@***.*** Xrootd_Protocol: 0100 0 fh=0 write ***@***.***
230306 12:50:39 2465330 ***@***.*** ofs_write: ***@***.*** fn=/eic/eic2/transfer/eic-xrdcp.JuRZGk
230306 12:50:39 2465330 ***@***.*** Xrootd_Response: 0100 sending OK
230306 12:50:39 2465330 ***@***.*** Xrootd_Protocol: 0100 req=close dlen=0
230306 12:50:39 2465330 ***@***.*** Xrootd_File: serializing access w Ref=0 /eic/eic2/transfer/eic-xrdcp.JuRZGk
230306 12:50:39 2465330 ***@***.*** ofs_close: use=1 fn=/eic/eic2/transfer/eic-xrdcp.JuRZGk
230306 12:50:39 2465330 ***@***.*** Xrootd_Protocol: 0100 fh=0 close rc=0
230306 12:50:39 2465330 ***@***.*** Xrootd_File: serializing access w Ref=0 /eic/eic2/transfer/eic-xrdcp.JuRZGk
230306 12:50:39 2465330 ***@***.*** Xrootd_File: closing w /eic/eic2/transfer/eic-xrdcp.JuRZGk
230306 12:50:39 2465330 ***@***.*** ofs_close: use=0 fn=dummy
230306 12:50:39 2465330 ***@***.*** Xrootd_Response: 0100 sending OK
[2023-03-06 12:50:39.609635 -0500][Error ][TlsMsg ] ***@***.*** TLS error rc=0 ec=6 (zero_return) errno=0.
230306 12:50:39 2465330 XrootdXeq: ***@***.*** disc 0:00:00
```
origin log, good case:
```
***@***.*** Grps ''
***@***.*** Caps ''
***@***.*** Pidn ***@***.***'
***@***.*** Mon ''
***@***.*** Crlen 897
***@***.*** ueid 11
***@***.*** uid 0
***@***.*** gid 0
***@***.*** Attr xrd.appname = 'xrdcp'
***@***.*** Attr = ''
230306 12:50:39 3233174 XrootdXeq: ***@***.*** pub IP46 TLSv1.3 login as http://cilogon.org/serverA/users/6772316 via ztn auth for ***@***.***
230306 12:50:39 3233174 multiuser_UserSentry: Failure when looking up UID for username http://cilogon.org/serverA/users/6772316 No such file or directory
230306 12:50:39 3233174 ***@***.*** Xrootd_Protocol: 0100 req=stat dlen=19
230306 12:50:39 3233174 ***@***.*** ofs_stat: fn=/eic/eic2/transfer/
230306 12:50:39 3233174 scitokens_Access: Trying token-based access control
230306 12:50:39 3233174 scitokens_Reconfig: Parsing configuration file: /etc/xrootd/scitokens.cfg
230306 12:50:39 3233174 scitokens_Reconfig: Configuring issuer https://cilogon.org/eic
230306 12:50:39 3233174 scitokens_Reconfig: Configuring issuer https://cilogon.org/jlab
230306 12:50:39 3233174 scitokens_Reconfig: Successfully parsed SciTokens mapfile: /etc/xrootd/scitokens-map.json
230306 12:50:39 3233174 scitokens_Access: Token not found in recent cache; parsing.
230306 12:50:39 3233174 scitokens_Access: New valid token mapped_username=osg-eic, subject=http://cilogon.org/serverA/users/6772316, issuer=https://cilogon.org/eic, authorizations=/eic:read,dir,stat,create,mkdir,mv,insert,update,chmod,del
230306 12:50:39 3233174 scitokens_Access: Grant authorization based on scopes for operation=stat, path=/eic/eic2/transfer/
230306 12:50:39 3233174 scitokens_Access: Request username osg-eic
230306 12:50:39 3233174 multiuser_UserSentry: Switching FS uid for user osg-eic
230306 12:50:39 3233174 ***@***.*** Xrootd_Protocol: 0100 rc=0 stat /eic/eic2/transfer/
230306 12:50:39 3233174 ***@***.*** Xrootd_Response: 0100 sending 76 data bytes
230306 12:50:39 3233174 ***@***.*** Xrootd_Protocol: 0100 req=open dlen=48
230306 12:50:39 3233174 ***@***.*** Xrootd_Protocol: 0100 open udmt /eic/eic2/transfer/eic-xrdcp.JuRZGk?oss.asize=48
230306 12:50:39 3233174 ***@***.*** ofs_open: 200-40644 fn=/eic/eic2/transfer/eic-xrdcp.JuRZGk
230306 12:50:39 3233174 scitokens_Access: Trying token-based access control
230306 12:50:39 3233174 scitokens_Access: Cached token mapped_username=osg-eic, subject=http://cilogon.org/serverA/users/6772316, issuer=https://cilogon.org/eic, authorizations=/eic:read,dir,stat,create,mkdir,mv,insert,update,chmod,del
230306 12:50:39 3233174 scitokens_Access: Grant authorization based on scopes for operation=create, path=/eic/eic2/transfer/eic-xrdcp.JuRZGk
230306 12:50:39 3233174 scitokens_Access: Request username osg-eic
230306 12:50:39 3233174 multiuser_UserSentry: Switching FS uid for user osg-eic
230306 12:50:39 3233174 multiuser_UserSentry: Switching FS uid for user osg-eic
230306 12:50:39 3233174 ***@***.*** oss_Open_ufs: fd=32768 flags=202 mode=40644 path=/xrd/eic/eic2/transfer/eic-xrdcp.JuRZGk
230306 12:50:39 3233174 multiuser_Open: Will not create checksum
230306 12:50:39 3233174 ***@***.*** ofs_fstat: fn=/eic/eic2/transfer/eic-xrdcp.JuRZGk
230306 12:50:39 3233174 ***@***.*** Xrootd_Response: 0100 sending 86 data bytes; status=0
230306 12:50:39 3233174 ***@***.*** Xrootd_Protocol: 0100 req=write dlen=48
230306 12:50:39 3233174 ***@***.*** Xrootd_Protocol: 0100 0 fh=0 write ***@***.***
230306 12:50:39 3233174 ***@***.*** ofs_write: ***@***.*** fn=/eic/eic2/transfer/eic-xrdcp.JuRZGk
230306 12:50:39 3233174 ***@***.*** Xrootd_Response: 0100 sending OK
230306 12:50:39 3233174 ***@***.*** Xrootd_Protocol: 0100 req=close dlen=0
230306 12:50:39 3233174 ***@***.*** Xrootd_File: serializing access w Ref=0 /eic/eic2/transfer/eic-xrdcp.JuRZGk
230306 12:50:39 3233174 ***@***.*** ofs_close: use=1 fn=/eic/eic2/transfer/eic-xrdcp.JuRZGk
230306 12:50:39 3233174 ***@***.*** Xrootd_Protocol: 0100 fh=0 close rc=0
230306 12:50:39 3233174 ***@***.*** Xrootd_File: serializing access w Ref=0 /eic/eic2/transfer/eic-xrdcp.JuRZGk
230306 12:50:39 3233174 ***@***.*** Xrootd_File: closing w /eic/eic2/transfer/eic-xrdcp.JuRZGk
230306 12:50:39 3233174 ***@***.*** ofs_close: use=0 fn=dummy
230306 12:50:39 3233174 ***@***.*** Xrootd_Response: 0100 sending OK
230306 12:50:42 3233174 ***@***.*** Xrootd_Protocol: 0100 request timeout; read 0 of 24 bytes
```
--
Reply to this email directly or view it on GitHub:
#1943
You are receiving this because you are subscribed to this thread.
Message ID: ***@***.***>
########################################################################
Use REPLY-ALL to reply to list
To unsubscribe from the XROOTD-DEV list, click the following link:
https://listserv.slac.stanford.edu/cgi-bin/wa?SUBED1=XROOTD-DEV&A=1
|
yes, there is a case attached where it works, above. The second set of logs in my original note. I agree that it is strange that the name is set that way, but it works despite that because of the ztn mapping on the origin in the good/working case. |
My bad, sorry IO didn't read all the way through. Unfortunately, in the
sucess case the "name" field appears to be clipped so we still don't know
what the value is upon success. Could you include that?
…On Mon, 6 Mar 2023, Bryan Hess wrote:
yes, there is a case attached where it works, above. The second set of logs in my original note. I agree that it is strange that the name is set that way, but it works despite that because of the ztn mapping on the origin in the good/working case.
--
Reply to this email directly or view it on GitHub:
#1943 (comment)
You are receiving this because you are subscribed to this thread.
Message ID: ***@***.***>
|
In both he successful and the unsuccesful case the name is the subject from the scitoken on the proxy, e.g. In the successful case, the ztn plugin maps the subject Name to a unix user via either the default user or the scitokens map file. |
I think this has been resolved as a multi-user plugin issue. I'll keep this open for a few more days then close it. |
The main difference I noticed between the two cases is that in the working case it's using TLSv1.2 and in the broken case it's using TLSv1.3. We have other reports with problems where I noticed TLSv1.3 is present, so that is likely the true source of the problem. |
@cantrip Do you confirm the above? Can this be closed as a multi-user plugin issue? |
Hello, I have what seems to be a race condition writing files through a proxy server. The proxy passes the credentials to the origin, where the the multiuser plugin is used to write the file as a default_user mapped in scitokens.cfg.
If I run the same xrdcp repeatedly, it will work ~90% of the time, occasionally failing with "permission denied" which I assume happens because the origin server does not switch UIDs in that instance(?) I can find no pattern to the failure. When writing directly to the origin, bypassing the proxy, it always succeeds. I suspect something in the config of the proxy, or some race condition on the origin related to sss+ztn and multiuser.
Here are the two configs and examples of log files from both the successful and the failing cases.
Any pointers greatly appreciated.
proxy config (dtn2201):
origin config (scifs2103):
Command line examples, no changes in between:
proxy log for the failing case:
origin log for the failing case:
proxy log, working case:
origin log, good case:
The text was updated successfully, but these errors were encountered: