 |
 |
I believe there was bug introduced in this commit:
https://github.com/xrootd/xrootd/blob/2be1931d8a058391be411859350ced50db583506/src/XrdCl/XrdClXRootDTransport.cc#L1632
which now drops the support for negotiation of the authentication mechanism between the client and the server. The "if" in the code before was removing any opaque data that started with "xrd." now it only forwards the opaque info that starts with "xrd." or "xrdcl." This will leave out all the authentication information the the server supports, namely the "&P=sss&P=unix" etc.
Therefore, at this point the TCP copy in EOS works only for instances with the same sss key as the client never tries to use the unix authentication (this is for the last step of the TPC transfer when the destination does the final open to do the reading). Below you have a debug log of what happens only with the relevant part of the authentication negotiation process:
[2018-01-31 17:17:49.221807 +0100][Debug ][PostMaster ] Creating new channel to: p05614920x00439.cern.ch:1095 1 stream(s)
[2018-01-31 17:17:49.221826 +0100][Debug ][PostMaster ] [p05614920x00439.cern.ch:1095 #0] Stream parameters: Network Stack: IPAuto, Connection Window: 5, ConnectionRetry: 1, Stream Error Widnow: 0
[2018-01-31 17:17:49.221914 +0100][Debug ][TaskMgr ] Registering task: "TickGeneratorTask for: p05614920x00439.cern.ch:1095" to be run at: [2018-01-31 17:17:50 +0100]
[2018-01-31 17:17:49.221929 +0100][Dump ][PostMaster ] [p05614920x00439.cern.ch:1095 #0] Sending message kXR_open (file: /eos/opstest/esindril/replica/test1.dat?fst.readahead=true&tpc.key=000324ad25ee5e7a5a71ec2d&[log in to unmask], mode: 00, flags: kX
R_open_read kXR_async kXR_retstat ) (0x3f260150) through substream 0 expecting answer at 0
[2018-01-31 17:17:49.221990 +0100][Debug ][PostMaster ] [p05614920x00439.cern.ch:1095] Found 2 address(es): [2001:1458:301:12::100:16]:1095, [::ffff:128.142.208.246]:1095
[2018-01-31 17:17:49.222036 +0100][Debug ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Attempting connection to [2001:1458:301:12::100:16]:1095
[2018-01-31 17:17:49.222108 +0100][Debug ][Poller ] Adding socket 0x3f268080 to the poller
[2018-01-31 17:17:49.222809 +0100][Debug ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Async connection call returned
[2018-01-31 17:17:49.222849 +0100][Debug ][XRootDTransport ] [p05614920x00439.cern.ch:1095 #0.0] Sending out the initial hand shake + kXR_protocol
[2018-01-31 17:17:49.222882 +0100][Dump ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Wrote a message: (0x4165e9a0), 44 bytes
[2018-01-31 17:17:49.223231 +0100][Dump ][XRootDTransport ] [msg: 0x4165e9a0] Expecting 8 bytes of message body
[2018-01-31 17:17:49.223257 +0100][Dump ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Received message header, size: 8
[2018-01-31 17:17:49.223265 +0100][Dump ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Received a message of 16 bytes
[2018-01-31 17:17:49.223274 +0100][Debug ][XRootDTransport ] [p05614920x00439.cern.ch:1095 #0.0] Got the server hand shake response (type: server [], protocol version 310)
[2018-01-31 17:17:49.223284 +0100][Dump ][XRootDTransport ] [msg: 0x4165e9a0] Expecting 8 bytes of message body
[2018-01-31 17:17:49.223289 +0100][Dump ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Received message header, size: 8
[2018-01-31 17:17:49.223295 +0100][Dump ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Received a message of 16 bytes
[2018-01-31 17:17:49.223300 +0100][Debug ][XRootDTransport ] [p05614920x00439.cern.ch:1095 #0.0] kXR_protocol successful (type: server [], protocol version 310)
[2018-01-31 17:17:49.223429 +0100][Debug ][XRootDTransport ] [p05614920x00439.cern.ch:1095 #0.0] Sending out kXR_login request, username: daemon, cgi: ?xrd.cc=ch&xrd.tz=1&xrd.appname=xrootd&xrd.info=&xrd.hostname=esdss000.cern.ch&xrd.rn=v4.8.0, dual-stack: true, private IPv4: fa
lse, private IPv6: false
[2018-01-31 17:17:49.223458 +0100][Dump ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Wrote a message: (0x51535060), 116 bytes
[2018-01-31 17:17:49.224022 +0100][Dump ][XRootDTransport ] [msg: 0x51535060] Expecting 50 bytes of message body
[2018-01-31 17:17:49.224041 +0100][Dump ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Received message header, size: 8
[2018-01-31 17:17:49.224048 +0100][Dump ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Received a message of 58 bytes
[2018-01-31 17:17:49.224056 +0100][Debug ][XRootDTransport ] [p05614920x00439.cern.ch:1095 #0.0] Logged in, session: 4dc80000896800007201000089c80000
[2018-01-31 17:17:49.224070 +0100][Debug ][XRootDTransport ] [p05614920x00439.cern.ch:1095 #0.0] Authentication is required: &P=unix&P=sss,0.13:/etc/eos.keytab
[2018-01-31 17:17:49.224075 +0100][Debug ][XRootDTransport ] [p05614920x00439.cern.ch:1095 #0.0] Sending authentication data
[2018-01-31 17:17:49.224113 +0100][Debug ][XRootDTransport ] [p05614920x00439.cern.ch:1095 #0.0] Trying to authenticate using sss
[2018-01-31 17:17:49.224194 +0100][Dump ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Wrote a message: (0x51535240), 175 bytes
[2018-01-31 17:17:49.224571 +0100][Dump ][XRootDTransport ] [msg: 0x51535240] Expecting 30 bytes of message body
[2018-01-31 17:17:49.224577 +0100][Dump ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Received message header, size: 8
[2018-01-31 17:17:49.224582 +0100][Dump ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Received a message of 38 bytes
[2018-01-31 17:17:49.224587 +0100][Error ][XRootDTransport ] [p05614920x00439.cern.ch:1095 #0.0] Authentication with sss failed: Decryption key not found.
[2018-01-31 17:17:49.224593 +0100][Error ][XRootDTransport ] [p05614920x00439.cern.ch:1095 #0.0] No protocols left to try
[2018-01-31 17:17:49.224600 +0100][Error ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Socket error while handshaking: [FATAL] Auth failed
[2018-01-31 17:17:49.224604 +0100][Debug ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Closing the socket
[2018-01-31 17:17:49.224609 +0100][Debug ][Poller ] <[2001:1458:202:229::100:3f]:55336><--><[2001:1458:301:12::100:16]:1095> Removing socket from the poller
[2018-01-31 17:17:49.224635 +0100][Error ][PostMaster ] [p05614920x00439.cern.ch:1095 #0] elapsed = 0, pConnectionWindow = 5 seconds.
[2018-01-31 17:17:49.224668 +0100][Debug ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Attempting connection to [::ffff:128.142.208.246]:1095
[2018-01-31 17:17:49.224701 +0100][Debug ][Poller ] Adding socket 0x3f268080 to the poller
[2018-01-31 17:17:49.225163 +0100][Debug ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Async connection call returned
[2018-01-31 17:17:49.225218 +0100][Debug ][XRootDTransport ] [p05614920x00439.cern.ch:1095 #0.0] Sending out the initial hand shake + kXR_protocol
[2018-01-31 17:17:49.225247 +0100][Dump ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Wrote a message: (0x51535240), 44 bytes
[2018-01-31 17:17:49.225662 +0100][Dump ][XRootDTransport ] [msg: 0x51535240] Expecting 8 bytes of message body
[2018-01-31 17:17:49.225683 +0100][Dump ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Received message header, size: 8
[2018-01-31 17:17:49.225689 +0100][Dump ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Received a message of 16 bytes
[2018-01-31 17:17:49.225695 +0100][Debug ][XRootDTransport ] [p05614920x00439.cern.ch:1095 #0.0] Got the server hand shake response (type: server [], protocol version 310)
[2018-01-31 17:17:49.225703 +0100][Dump ][XRootDTransport ] [msg: 0x51535240] Expecting 8 bytes of message body
[2018-01-31 17:17:49.225707 +0100][Dump ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Received message header, size: 8
[2018-01-31 17:17:49.225711 +0100][Dump ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Received a message of 16 bytes
[2018-01-31 17:17:49.225716 +0100][Debug ][XRootDTransport ] [p05614920x00439.cern.ch:1095 #0.0] kXR_protocol successful (type: server [], protocol version 310)
[2018-01-31 17:17:49.225793 +0100][Debug ][XRootDTransport ] [p05614920x00439.cern.ch:1095 #0.0] Sending out kXR_login request, username: daemon, cgi: ?xrd.cc=ch&xrd.tz=1&xrd.appname=xrootd&xrd.info=&xrd.hostname=esdss000.cern.ch&xrd.rn=v4.8.0, dual-stack: true, private IPv4: fa
lse, private IPv6: false
[2018-01-31 17:17:49.225817 +0100][Dump ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Wrote a message: (0x51535060), 116 bytes
[2018-01-31 17:17:49.226237 +0100][Dump ][XRootDTransport ] [msg: 0x51535060] Expecting 50 bytes of message body
[2018-01-31 17:17:49.226251 +0100][Dump ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Received message header, size: 8
[2018-01-31 17:17:49.226256 +0100][Dump ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Received a message of 58 bytes
[2018-01-31 17:17:49.226263 +0100][Debug ][XRootDTransport ] [p05614920x00439.cern.ch:1095 #0.0] Logged in, session: 4ec8000089680000760100008ac80000
[2018-01-31 17:17:49.226267 +0100][Debug ][XRootDTransport ] [p05614920x00439.cern.ch:1095 #0.0] Authentication is required: &P=unix&P=sss,0.13:/etc/eos.keytab
[2018-01-31 17:17:49.226271 +0100][Debug ][XRootDTransport ] [p05614920x00439.cern.ch:1095 #0.0] Sending authentication data
[2018-01-31 17:17:49.226910 +0100][Debug ][XRootDTransport ] [p05614920x00439.cern.ch:1095 #0.0] Trying to authenticate using sss
[2018-01-31 17:17:49.226994 +0100][Dump ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Wrote a message: (0x515350f0), 175 bytes
[2018-01-31 17:17:49.227285 +0100][Dump ][XRootDTransport ] [msg: 0x515350f0] Expecting 30 bytes of message body
[2018-01-31 17:17:49.227295 +0100][Dump ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Received message header, size: 8
[2018-01-31 17:17:49.225711 +0100][Dump ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Received a message of 16 bytes
[2018-01-31 17:17:49.225716 +0100][Debug ][XRootDTransport ] [p05614920x00439.cern.ch:1095 #0.0] kXR_protocol successful (type: server [], protocol version 310)
[2018-01-31 17:17:49.225793 +0100][Debug ][XRootDTransport ] [p05614920x00439.cern.ch:1095 #0.0] Sending out kXR_login request, username: daemon, cgi: ?xrd.cc=ch&xrd.tz=1&xrd.appname=xrootd&xrd.info=&xrd.hostname=esdss000.cern.ch&xrd.rn=v4.8.0, dual-stack: true, private IPv4: fa
lse, private IPv6: false
[2018-01-31 17:17:49.225817 +0100][Dump ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Wrote a message: (0x51535060), 116 bytes
[2018-01-31 17:17:49.226237 +0100][Dump ][XRootDTransport ] [msg: 0x51535060] Expecting 50 bytes of message body
[2018-01-31 17:17:49.226251 +0100][Dump ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Received message header, size: 8
[2018-01-31 17:17:49.226256 +0100][Dump ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Received a message of 58 bytes
[2018-01-31 17:17:49.226263 +0100][Debug ][XRootDTransport ] [p05614920x00439.cern.ch:1095 #0.0] Logged in, session: 4ec8000089680000760100008ac80000
[2018-01-31 17:17:49.226267 +0100][Debug ][XRootDTransport ] [p05614920x00439.cern.ch:1095 #0.0] Authentication is required: &P=unix&P=sss,0.13:/etc/eos.keytab
[2018-01-31 17:17:49.226271 +0100][Debug ][XRootDTransport ] [p05614920x00439.cern.ch:1095 #0.0] Sending authentication data
[2018-01-31 17:17:49.226910 +0100][Debug ][XRootDTransport ] [p05614920x00439.cern.ch:1095 #0.0] Trying to authenticate using sss
[2018-01-31 17:17:49.226994 +0100][Dump ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Wrote a message: (0x515350f0), 175 bytes
[2018-01-31 17:17:49.227285 +0100][Dump ][XRootDTransport ] [msg: 0x515350f0] Expecting 30 bytes of message body
[2018-01-31 17:17:49.227295 +0100][Dump ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Received message header, size: 8
[2018-01-31 17:17:49.227300 +0100][Dump ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Received a message of 38 bytes
[2018-01-31 17:17:49.227305 +0100][Error ][XRootDTransport ] [p05614920x00439.cern.ch:1095 #0.0] Authentication with sss failed: Decryption key not found.
[2018-01-31 17:17:49.227311 +0100][Error ][XRootDTransport ] [p05614920x00439.cern.ch:1095 #0.0] No protocols left to try
[2018-01-31 17:17:49.227318 +0100][Error ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Socket error while handshaking: [FATAL] Auth failed
[2018-01-31 17:17:49.227322 +0100][Debug ][AsyncSock ] [p05614920x00439.cern.ch:1095 #0.0] Closing the socket
[2018-01-31 17:17:49.227327 +0100][Debug ][Poller ] <[::ffff:128.141.194.200]:41650><--><[::ffff:128.142.208.246]:1095> Removing socket from the poller
[2018-01-31 17:17:49.227346 +0100][Error ][PostMaster ] [p05614920x00439.cern.ch:1095 #0] elapsed = 0, pConnectionWindow = 5 seconds.
—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub, or mute the thread.
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