 |
 |
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 anon.0:34@ifarm1801 Xrootd_Protocol: 0000 req=protocol dlen=0 230306 12:49:21 2465329 anon.0:34@ifarm1801 Xrootd_Response: 0000 sending 8 data bytes; status=0 230306 12:49:21 2465329 XrdLinkXeq: anon.0:34@ifarm1801 connection upgraded to TLSv1.2 230306 12:49:21 2465329 anon.0:34@ifarm1801 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 bhess.225629:34@ifarm1801 Xrootd_Response: 0000 sending 65 data bytes; status=0 230306 12:49:21 2465329 bhess.225629:34@ifarm1801 Xrootd_Protocol: 0000 req=auth dlen=910 sec_PM: Using ztn protocol, args='0:4096:' 230306 12:49:21 2465329 bhess.225629:34@ifarm1801 Xrootd_Response: 0000 sending OK bhess.225629:34@ifarm1801 Protocol 'ztn' bhess.225629:34@ifarm1801 Name 'http://cilogon.org/serverA/users/6772316' bhess.225629:34@ifarm1801 Host 'ifarm1801.jlab.org' bhess.225629:34@ifarm1801 Vorg '' bhess.225629:34@ifarm1801 Role '' bhess.225629:34@ifarm1801 Grps '' bhess.225629:34@ifarm1801 Caps '' bhess.225629:34@ifarm1801 Pidn 'bhess.225629:34@ifarm1801' bhess.225629:34@ifarm1801 Mon '' bhess.225629:34@ifarm1801 Crlen 897 bhess.225629:34@ifarm1801 ueid 4 bhess.225629:34@ifarm1801 uid 0 bhess.225629:34@ifarm1801 gid 0 230306 12:49:21 2465329 XrootdXeq: bhess.225629:34@ifarm1801 pub IPv4 TLSv1.2 login as http://cilogon.org/serverA/users/6772316 230306 12:49:21 2465329 bhess.225629:34@ifarm1801 Xrootd_Protocol: 0100 req=stat dlen=19 230306 12:49:21 2465329 bhess.225629:34@ifarm1801 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: bhess.225629:34@ifarm1801 Unable to locate /eic/eic2/transfer/; permission denied 230306 12:49:21 2465329 bhess.225629:34@ifarm1801 Xrootd_Protocol: 0100 rc=-1 stat /eic/eic2/transfer/ 230306 12:49:21 2465329 bhess.225629:34@ifarm1801 Xrootd_Response: 0100 sending err 3010: Unable to locate /eic/eic2/transfer/; permission denied [2023-03-06 12:49:21.287124 -0500][Error ][TlsMsg ] [bhess.225629:34@ifarm1801] TLS error rc=0 ec=6 (zero_return) errno=0. 230306 12:49:21 2465329 XrootdXeq: bhess.225629:34@ifarm1801 disc 0:00:00 ``` origin log for the failing case: ``` 230306 12:49:21 3232959 anon.0:25@dtn2201 Xrootd_Protocol: 0000 req=protocol dlen=0 230306 12:49:21 3232959 anon.0:25@dtn2201 Xrootd_Response: 0000 sending 8 data bytes; status=0 230306 12:49:21 3232959 XrdLinkXeq: anon.0:25@dtn2201 connection upgraded to TLSv1.3 230306 12:49:21 3232959 anon.0:25@dtn2201 Xrootd_Protocol: 0000 req=login dlen=92 230306 12:49:21 3232959 U4.2465323:25@dtn2201 Xrootd_Response: 0000 sending 65 data bytes; status=0 230306 12:49:21 3232959 U4.2465323:25@dtn2201 Xrootd_Protocol: 0000 req=auth dlen=1171 230306 12:49:21 3232959 U4.2465323:25@dtn2201 Xrootd_Response: 0000 sending OK U4.2465323:25@dtn2201 Protocol 'ztn' U4.2465323:25@dtn2201 Name 'http://cilogon.org/serverA/users/6772316' U4.2465323:25@dtn2201 Host 'dtn2201.jlab.org' U4.2465323:25@dtn2201 Vorg '' U4.2465323:25@dtn2201 Role '' U4.2465323:25@dtn2201 Grps '' U4.2465323:25@dtn2201 Caps '' U4.2465323:25@dtn2201 Pidn 'bhess.225629:34@ifarm1801' U4.2465323:25@dtn2201 Mon '' U4.2465323:25@dtn2201 Crlen 897 U4.2465323:25@dtn2201 ueid 10 U4.2465323:25@dtn2201 uid 0 U4.2465323:25@dtn2201 gid 0 U4.2465323:25@dtn2201 Attr xrd.appname = 'xrdcp' U4.2465323:25@dtn2201 Attr = '' 230306 12:49:21 3232959 XrootdXeq: U4.2465323:25@dtn2201 pub IP46 TLSv1.3 login as http://cilogon.org/serverA/users/6772316 via ztn auth for bhess.225629:34@ifarm1801 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 U4.2465323:25@dtn2201 Xrootd_Protocol: 0100 req=stat dlen=19 230306 12:49:21 3232959 U4.2465323:25@dtn2201 ofs_stat: fn=/eic/eic2/transfer/ 230306 12:49:21 3232959 ofs_stat: U4.2465323:25@dtn2201 Unable to locate /eic/eic2/transfer/; permission denied 230306 12:49:21 3232959 U4.2465323:25@dtn2201 Xrootd_Protocol: 0100 rc=-1 stat /eic/eic2/transfer/ 230306 12:49:21 3232959 U4.2465323:25@dtn2201 Xrootd_Response: 0100 sending err 3010: Unable to locate /eic/eic2/transfer/; permission denied ``` proxy log, working case: ``` 230306 12:50:39 2465330 anon.0:32@ifarm1801 Xrootd_Response: 0000 sending 8 data bytes; status=0 230306 12:50:39 2465330 XrdLinkXeq: anon.0:32@ifarm1801 connection upgraded to TLSv1.2 230306 12:50:39 2465330 anon.0:32@ifarm1801 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 bhess.227751:32@ifarm1801 Xrootd_Response: 0000 sending 65 data bytes; status=0 230306 12:50:39 2465330 bhess.227751:32@ifarm1801 Xrootd_Protocol: 0000 req=auth dlen=910 sec_PM: Using ztn protocol, args='0:4096:' 230306 12:50:39 2465330 bhess.227751:32@ifarm1801 Xrootd_Response: 0000 sending OK bhess.227751:32@ifarm1801 Protocol 'ztn' bhess.227751:32@ifarm1801 Name 'http://cilogon.org/serverA/users/6772316' bhess.227751:32@ifarm1801 Host 'ifarm1801.jlab.org' bhess.227751:32@ifarm1801 Vorg '' bhess.227751:32@ifarm1801 Role '' bhess.227751:32@ifarm1801 Grps '' bhess.227751:32@ifarm1801 Caps '' bhess.227751:32@ifarm1801 Pidn 'bhess.227751:32@ifarm1801' bhess.227751:32@ifarm1801 Mon '' bhess.227751:32@ifarm1801 Crlen 897 bhess.227751:32@ifarm1801 ueid 5 bhess.227751:32@ifarm1801 uid 0 bhess.227751:32@ifarm1801 gid 0 230306 12:50:39 2465330 XrootdXeq: bhess.227751:32@ifarm1801 pub IPv4 TLSv1.2 login as http://cilogon.org/serverA/users/6772316 230306 12:50:39 2465330 bhess.227751:32@ifarm1801 Xrootd_Protocol: 0100 req=stat dlen=19 230306 12:50:39 2465330 bhess.227751:32@ifarm1801 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 bhess.227751:32@ifarm1801 Xrootd_Protocol: 0100 rc=0 stat /eic/eic2/transfer/ 230306 12:50:39 2465330 bhess.227751:32@ifarm1801 Xrootd_Response: 0100 sending 72 data bytes 230306 12:50:39 2465330 bhess.227751:32@ifarm1801 Xrootd_Protocol: 0100 req=open dlen=49 230306 12:50:39 2465330 bhess.227751:32@ifarm1801 Xrootd_Protocol: 0100 open udmat /eic/eic2/transfer//eic-xrdcp.JuRZGk?oss.asize=48 230306 12:50:39 2465330 bhess.227751:32@ifarm1801 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 bhess.227751:32@ifarm1801 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 bhess.227751:32@ifarm1801 ofs_fstat: fn=/eic/eic2/transfer/eic-xrdcp.JuRZGk 230306 12:50:39 2465330 bhess.227751:32@ifarm1801 Xrootd_Response: 0100 sending 82 data bytes; status=0 230306 12:50:39 2465330 bhess.227751:32@ifarm1801 Xrootd_Protocol: 0100 req=write dlen=48 230306 12:50:39 2465330 bhess.227751:32@ifarm1801 Xrootd_Protocol: 0100 0 fh=0 write 48@0 230306 12:50:39 2465330 bhess.227751:32@ifarm1801 ofs_write: 48@0 fn=/eic/eic2/transfer/eic-xrdcp.JuRZGk 230306 12:50:39 2465330 bhess.227751:32@ifarm1801 Xrootd_Response: 0100 sending OK 230306 12:50:39 2465330 bhess.227751:32@ifarm1801 Xrootd_Protocol: 0100 req=close dlen=0 230306 12:50:39 2465330 bhess.227751:32@ifarm1801 Xrootd_File: serializing access w Ref=0 /eic/eic2/transfer/eic-xrdcp.JuRZGk 230306 12:50:39 2465330 bhess.227751:32@ifarm1801 ofs_close: use=1 fn=/eic/eic2/transfer/eic-xrdcp.JuRZGk 230306 12:50:39 2465330 bhess.227751:32@ifarm1801 Xrootd_Protocol: 0100 fh=0 close rc=0 230306 12:50:39 2465330 bhess.227751:32@ifarm1801 Xrootd_File: serializing access w Ref=0 /eic/eic2/transfer/eic-xrdcp.JuRZGk 230306 12:50:39 2465330 bhess.227751:32@ifarm1801 Xrootd_File: closing w /eic/eic2/transfer/eic-xrdcp.JuRZGk 230306 12:50:39 2465330 bhess.227751:32@ifarm1801 ofs_close: use=0 fn=dummy 230306 12:50:39 2465330 bhess.227751:32@ifarm1801 Xrootd_Response: 0100 sending OK [2023-03-06 12:50:39.609635 -0500][Error ][TlsMsg ] [bhess.227751:32@ifarm1801] TLS error rc=0 ec=6 (zero_return) errno=0. 230306 12:50:39 2465330 XrootdXeq: bhess.227751:32@ifarm1801 disc 0:00:00 ``` origin log, good case: ``` U5.2465323:26@dtn2201 Grps '' U5.2465323:26@dtn2201 Caps '' U5.2465323:26@dtn2201 Pidn 'bhess.227751:32@ifarm1801' U5.2465323:26@dtn2201 Mon '' U5.2465323:26@dtn2201 Crlen 897 U5.2465323:26@dtn2201 ueid 11 U5.2465323:26@dtn2201 uid 0 U5.2465323:26@dtn2201 gid 0 U5.2465323:26@dtn2201 Attr xrd.appname = 'xrdcp' U5.2465323:26@dtn2201 Attr = '' 230306 12:50:39 3233174 XrootdXeq: U5.2465323:26@dtn2201 pub IP46 TLSv1.3 login as http://cilogon.org/serverA/users/6772316 via ztn auth for bhess.227751:32@ifarm1801 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 U5.2465323:26@dtn2201 Xrootd_Protocol: 0100 req=stat dlen=19 230306 12:50:39 3233174 U5.2465323:26@dtn2201 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 U5.2465323:26@dtn2201 Xrootd_Protocol: 0100 rc=0 stat /eic/eic2/transfer/ 230306 12:50:39 3233174 U5.2465323:26@dtn2201 Xrootd_Response: 0100 sending 76 data bytes 230306 12:50:39 3233174 U5.2465323:26@dtn2201 Xrootd_Protocol: 0100 req=open dlen=48 230306 12:50:39 3233174 U5.2465323:26@dtn2201 Xrootd_Protocol: 0100 open udmt /eic/eic2/transfer/eic-xrdcp.JuRZGk?oss.asize=48 230306 12:50:39 3233174 U5.2465323:26@dtn2201 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 U5.2465323:26@dtn2201 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 U5.2465323:26@dtn2201 ofs_fstat: fn=/eic/eic2/transfer/eic-xrdcp.JuRZGk 230306 12:50:39 3233174 U5.2465323:26@dtn2201 Xrootd_Response: 0100 sending 86 data bytes; status=0 230306 12:50:39 3233174 U5.2465323:26@dtn2201 Xrootd_Protocol: 0100 req=write dlen=48 230306 12:50:39 3233174 U5.2465323:26@dtn2201 Xrootd_Protocol: 0100 0 fh=0 write 48@0 230306 12:50:39 3233174 U5.2465323:26@dtn2201 ofs_write: 48@0 fn=/eic/eic2/transfer/eic-xrdcp.JuRZGk 230306 12:50:39 3233174 U5.2465323:26@dtn2201 Xrootd_Response: 0100 sending OK 230306 12:50:39 3233174 U5.2465323:26@dtn2201 Xrootd_Protocol: 0100 req=close dlen=0 230306 12:50:39 3233174 U5.2465323:26@dtn2201 Xrootd_File: serializing access w Ref=0 /eic/eic2/transfer/eic-xrdcp.JuRZGk 230306 12:50:39 3233174 U5.2465323:26@dtn2201 ofs_close: use=1 fn=/eic/eic2/transfer/eic-xrdcp.JuRZGk 230306 12:50:39 3233174 U5.2465323:26@dtn2201 Xrootd_Protocol: 0100 fh=0 close rc=0 230306 12:50:39 3233174 U5.2465323:26@dtn2201 Xrootd_File: serializing access w Ref=0 /eic/eic2/transfer/eic-xrdcp.JuRZGk 230306 12:50:39 3233174 U5.2465323:26@dtn2201 Xrootd_File: closing w /eic/eic2/transfer/eic-xrdcp.JuRZGk 230306 12:50:39 3233174 U5.2465323:26@dtn2201 ofs_close: use=0 fn=dummy 230306 12:50:39 3233174 U5.2465323:26@dtn2201 Xrootd_Response: 0100 sending OK 230306 12:50:42 3233174 U5.2465323:26@dtn2201 Xrootd_Protocol: 0100 request timeout; read 0 of 24 bytes ``` -- Reply to this email directly or view it on GitHub: https://github.com/xrootd/xrootd/issues/1943 You are receiving this because you are subscribed to this thread. Message ID: <[log in to unmask]> ######################################################################## 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