[FATAL] TLS error: resource temporarily unavailable #2082

ivmfnal · 2023-09-05T18:41:55Z

Lately, xrdfs ls and xrdfs stat commands started failing for several sites CMS uses for storage. They consistently fail with the error:

[FATAL] TLS error: resource temporarily unavailable

Here are some relevant lines from xrdfs debug output:

[2023-09-05 13:52:00.106454 +0000][Debug  ][AsyncSock         ] [xrootd15.cmsaf.mit.edu:1094.0] TLS hand-shake exchange.
[2023-09-05 13:52:00.199610 +0000][Debug  ][AsyncSock         ] [xrootd15.cmsaf.mit.edu:1094.0] TLS hand-shake exchange.
[2023-09-05 13:52:00.200013 +0000][Error  ][TlsMsg            ] [] TLS error rc=-1 ec=1 (error_ssl) errno=0.
[2023-09-05 13:52:00.200277 +0000][Debug  ][TlsMsg            ] [] 140481527695104:error:140770FC:SSL routines:SSL23_GET_SERVER_HELLO:unknown protocol:s23_clnt.c:794:
[2023-09-05 13:52:00.200321 +0000][Error  ][TlsMsg            ] Failed to do TLS connect: Unable to connect to xrootd15.cmsaf.mit.edu; error_ssl
[2023-09-05 13:52:00.200335 +0000][Error  ][AsyncSock         ] [xrootd15.cmsaf.mit.edu:1094.0] Socket error while handshaking: [FATAL] TLS error: resource temporarily unavailable

xrootd-client rpm installed: xrootd-client.x86_64 1:5.6.1-1.el7

and complete debug output is:

[2023-09-05 13:51:59.915360 +0000][Debug  ][Utility           ] Initializing xrootd client version: v5.6.1
[2023-09-05 13:51:59.915956 +0000][Debug  ][Utility           ] Unable to process user config file: [ERROR] OS Error: no such file or directory
[2023-09-05 13:51:59.916300 +0000][Debug  ][PlugInMgr         ] Initializing plug-in manager...
[2023-09-05 13:51:59.916329 +0000][Debug  ][PlugInMgr         ] No default plug-in, loading plug-in configs...
[2023-09-05 13:51:59.916337 +0000][Debug  ][PlugInMgr         ] Processing plug-in definitions in /etc/xrootd/client.plugins.d...
[2023-09-05 13:51:59.916614 +0000][Debug  ][PlugInMgr         ] Trying to disable plug-in for '*'
[2023-09-05 13:51:59.916742 +0000][Debug  ][PlugInMgr         ] Processing plug-in definitions in /root/.xrootd/client.plugins.d...
[2023-09-05 13:51:59.917037 +0000][Debug  ][PlugInMgr         ] Unable to process directory /root/.xrootd/client.plugins.d: [ERROR] OS Error: no such file or directory
[2023-09-05 13:51:59.918969 +0000][Debug  ][App               ] Executing: ls /store/mc 
[2023-09-05 13:51:59.919000 +0000][Debug  ][App               ] Attempting to stat: /store/mc
[2023-09-05 13:51:59.919053 +0000][Debug  ][Utility           ] Env: trying to get a non-existent string entry: pollerpreference
[2023-09-05 13:51:59.919074 +0000][Debug  ][Poller            ] Available pollers: built-in
[2023-09-05 13:51:59.919157 +0000][Debug  ][Poller            ] Attempting to create a poller according to preference: built-in
[2023-09-05 13:51:59.919187 +0000][Debug  ][Poller            ] Creating poller: built-in
[2023-09-05 13:51:59.919201 +0000][Debug  ][Poller            ] Creating and starting the built-in poller...
[2023-09-05 13:51:59.920717 +0000][Debug  ][Poller            ] Using 10 poller threads
[2023-09-05 13:51:59.920762 +0000][Debug  ][TaskMgr           ] Starting the task manager...
[2023-09-05 13:51:59.920895 +0000][Debug  ][TaskMgr           ] Task manager started
[2023-09-05 13:51:59.920919 +0000][Debug  ][JobMgr            ] Starting the job manager...
[2023-09-05 13:51:59.921130 +0000][Debug  ][JobMgr            ] Job manager started, 3 workers
[2023-09-05 13:51:59.921153 +0000][Debug  ][TaskMgr           ] Registering task: "FileTimer task" to be run at: [2023-09-05 13:51:59 +0000]
[2023-09-05 13:51:59.921305 +0000][Debug  ][ExDbgMsg          ] [xrootd15.cmsaf.mit.edu:1094] MsgHandler created: 0x11c1010 (message: kXR_stat (path: /store/mc, flags: none) ).
[2023-09-05 13:51:59.921446 +0000][Debug  ][PostMaster        ] Creating new channel to: root://xrootd15.cmsaf.mit.edu:1094/
[2023-09-05 13:51:59.921603 +0000][Debug  ][PostMaster        ] [xrootd15.cmsaf.mit.edu:1094] Stream parameters: Network Stack: IPAuto, Connection Window: 120, ConnectionRetry: 5, Stream Error Window: 1800
[2023-09-05 13:51:59.921716 +0000][Debug  ][TaskMgr           ] Registering task: "TickGeneratorTask for: root://xrootd15.cmsaf.mit.edu:1094/" to be run at: [2023-09-05 13:52:14 +0000]
[2023-09-05 13:51:59.925602 +0000][Debug  ][PostMaster        ] [xrootd15.cmsaf.mit.edu:1094] Found 1 address(es): [::ffff:18.12.1.55]:1094
[2023-09-05 13:51:59.925659 +0000][Debug  ][AsyncSock         ] [xrootd15.cmsaf.mit.edu:1094.0] Attempting connection to [::ffff:18.12.1.55]:1094
[2023-09-05 13:51:59.925746 +0000][Debug  ][Poller            ] Adding socket 0x11c17f0 to the poller
[2023-09-05 13:52:00.015264 +0000][Debug  ][AsyncSock         ] [xrootd15.cmsaf.mit.edu:1094.0] Async connection call returned
[2023-09-05 13:52:00.015683 +0000][Debug  ][XRootDTransport   ] [xrootd15.cmsaf.mit.edu:1094.0] Sending out the initial hand shake + kXR_protocol
[2023-09-05 13:52:00.105883 +0000][Debug  ][XRootDTransport   ] [xrootd15.cmsaf.mit.edu:1094.0] Got the server hand shake response (type: server [], protocol version 511)
[2023-09-05 13:52:00.106058 +0000][Debug  ][XRootDTransport   ] [xrootd15.cmsaf.mit.edu:1094.0] kXR_protocol successful (type: server [], protocol version 511)
[2023-09-05 13:52:00.106424 +0000][Debug  ][XRootDTransport   ] [xrootd15.cmsaf.mit.edu:1094.0] Sending out kXR_login request, username: root, cgi: xrd.cc=us&xrd.tz=0&xrd.appname=xrdfs&xrd.info=&xrd.hostname=consistency-rucio-consistency-5869ffb5c8-d6wwr&xrd.rn=v5.6.1, dual-stack: false, private IPv4: true, private IPv6: false
[2023-09-05 13:52:00.106454 +0000][Debug  ][AsyncSock         ] [xrootd15.cmsaf.mit.edu:1094.0] TLS hand-shake exchange.
[2023-09-05 13:52:00.199610 +0000][Debug  ][AsyncSock         ] [xrootd15.cmsaf.mit.edu:1094.0] TLS hand-shake exchange.
[2023-09-05 13:52:00.200013 +0000][Error  ][TlsMsg            ] [] TLS error rc=-1 ec=1 (error_ssl) errno=0.
[2023-09-05 13:52:00.200277 +0000][Debug  ][TlsMsg            ] [] 140481527695104:error:140770FC:SSL routines:SSL23_GET_SERVER_HELLO:unknown protocol:s23_clnt.c:794:
[2023-09-05 13:52:00.200321 +0000][Error  ][TlsMsg            ] Failed to do TLS connect: Unable to connect to xrootd15.cmsaf.mit.edu; error_ssl
[2023-09-05 13:52:00.200335 +0000][Error  ][AsyncSock         ] [xrootd15.cmsaf.mit.edu:1094.0] Socket error while handshaking: [FATAL] TLS error: resource temporarily unavailable
[2023-09-05 13:52:00.200390 +0000][Debug  ][AsyncSock         ] [xrootd15.cmsaf.mit.edu:1094.0] Closing the socket
[2023-09-05 13:52:00.200634 +0000][Debug  ][Poller            ] <[::ffff:10.100.197.146]:45450><--><[::ffff:18.12.1.55]:1094> Removing socket from the poller
[2023-09-05 13:52:00.200889 +0000][Error  ][PostMaster        ] [xrootd15.cmsaf.mit.edu:1094] elapsed = 1, pConnectionWindow = 120 seconds.
[2023-09-05 13:52:00.200914 +0000][Error  ][PostMaster        ] [xrootd15.cmsaf.mit.edu:1094] Unable to recover: [FATAL] TLS error: resource temporarily unavailable.
[2023-09-05 13:52:00.200925 +0000][Error  ][XRootD            ] [xrootd15.cmsaf.mit.edu:1094] Impossible to send message kXR_stat (path: /store/mc, flags: none). Trying to recover.
[2023-09-05 13:52:00.201118 +0000][Debug  ][XRootD            ] [xrootd15.cmsaf.mit.edu:1094] Handling error while processing kXR_stat (path: /store/mc, flags: none): [FATAL] TLS error: resource temporarily unavailable.
[2023-09-05 13:52:00.201168 +0000][Info   ][XRootD            ] [xrootd15.cmsaf.mit.edu:1094] Retrying request: kXR_stat (path: /store/mc, flags: none).
[2023-09-05 13:52:00.201438 +0000][Debug  ][ExDbgMsg          ] [xrootd15.cmsaf.mit.edu:1094] Retry at server MsgHandler: 0x11c1010 (message: kXR_stat (path: /store/mc?tried=xrootd15.cmsaf.mit.edu&triedrc=srverr, flags: none) ).
[2023-09-05 13:52:00.201498 +0000][Debug  ][XRootD            ] [xrootd15.cmsaf.mit.edu:1094] Handling error while processing kXR_stat (path: /store/mc?tried=xrootd15.cmsaf.mit.edu&triedrc=srverr, flags: none): [FATAL] TLS error: resource temporarily unavailable.
[2023-09-05 13:52:00.201510 +0000][Info   ][XRootD            ] [xrootd15.cmsaf.mit.edu:1094] Retrying request: kXR_stat (path: /store/mc?tried=xrootd15.cmsaf.mit.edu&triedrc=srverr, flags: none).
[2023-09-05 13:52:00.201909 +0000][Debug  ][ExDbgMsg          ] [xrootd15.cmsaf.mit.edu:1094] Retry at server MsgHandler: 0x11c1010 (message: kXR_stat (path: /store/mc?tried=xrootd15.cmsaf.mit.edu,xrootd15.cmsaf.mit.edu&triedrc=srverr,srverr, flags: none) ).
[2023-09-05 13:52:00.201937 +0000][Debug  ][XRootD            ] [xrootd15.cmsaf.mit.edu:1094] Handling error while processing kXR_stat (path: /store/mc?tried=xrootd15.cmsaf.mit.edu,xrootd15.cmsaf.mit.edu&triedrc=srverr,srverr, flags: none): [FATAL] TLS error: resource temporarily unavailable.
[2023-09-05 13:52:00.201946 +0000][Info   ][XRootD            ] [xrootd15.cmsaf.mit.edu:1094] Retrying request: kXR_stat (path: /store/mc?tried=xrootd15.cmsaf.mit.edu,xrootd15.cmsaf.mit.edu&triedrc=srverr,srverr, flags: none).
[2023-09-05 13:52:00.202337 +0000][Debug  ][ExDbgMsg          ] [xrootd15.cmsaf.mit.edu:1094] Retry at server MsgHandler: 0x11c1010 (message: kXR_stat (path: /store/mc?tried=xrootd15.cmsaf.mit.edu,xrootd15.cmsaf.mit.edu,xrootd15.cmsaf.mit.edu&triedrc=srverr,srverr,srverr, flags: none) ).
[2023-09-05 13:52:00.202403 +0000][Debug  ][XRootD            ] [xrootd15.cmsaf.mit.edu:1094] Handling error while processing kXR_stat (path: /store/mc?tried=xrootd15.cmsaf.mit.edu,xrootd15.cmsaf.mit.edu,xrootd15.cmsaf.mit.edu&triedrc=srverr,srverr,srverr, flags: none): [FATAL] TLS error: resource temporarily unavailable.
[2023-09-05 13:52:00.202558 +0000][Debug  ][ExDbgMsg          ] [xrootd15.cmsaf.mit.edu:1094] Passing to the thread-pool MsgHandler: 0x11c1010 (message: kXR_stat (path: /store/mc?tried=xrootd15.cmsaf.mit.edu,xrootd15.cmsaf.mit.edu,xrootd15.cmsaf.mit.edu&triedrc=srverr,srverr,srverr, flags: none) ).
[2023-09-05 13:52:00.202849 +0000][Debug  ][ExDbgMsg          ] [xrootd15.cmsaf.mit.edu:1094] Calling MsgHandler: 0x11c1010 (message: kXR_stat (path: /store/mc?tried=xrootd15.cmsaf.mit.edu,xrootd15.cmsaf.mit.edu,xrootd15.cmsaf.mit.edu&triedrc=srverr,srverr,srverr, flags: none) ) with status: [FATAL] TLS error: resource temporarily unavailable.
[2023-09-05 13:52:00.202923 +0000][Debug  ][XRootD            ] Redirect trace-back:
[2023-09-05 13:52:00.202923 +0000][Debug  ][XRootD            ] 	0. Retrying: root://xrootd15.cmsaf.mit.edu:1094/
[2023-09-05 13:52:00.202923 +0000][Debug  ][XRootD            ] 	1. Retrying: root://xrootd15.cmsaf.mit.edu:1094/
[2023-09-05 13:52:00.202923 +0000][Debug  ][XRootD            ] 	2. Retrying: root://xrootd15.cmsaf.mit.edu:1094/
[2023-09-05 13:52:00.202947 +0000][Debug  ][ExDbgMsg          ] [xrootd15.cmsaf.mit.edu:1094] Destroying MsgHandler: 0x11c1010.
[2023-09-05 13:52:00.202967 +0000][Error  ][App               ] Unable to stat the path: [FATAL] TLS error: resource temporarily unavailable
[FATAL] TLS error: resource temporarily unavailable
[2023-09-05 13:52:00.203426 +0000][Debug  ][JobMgr            ] Stopping the job manager...
[2023-09-05 13:52:00.203967 +0000][Debug  ][JobMgr            ] Job manager stopped
[2023-09-05 13:52:00.204000 +0000][Debug  ][TaskMgr           ] Stopping the task manager...
[2023-09-05 13:52:00.204156 +0000][Debug  ][TaskMgr           ] Task manager stopped
[2023-09-05 13:52:00.204173 +0000][Debug  ][Poller            ] Stopping the poller...
[2023-09-05 13:52:00.204940 +0000][Debug  ][AsyncSock         ] [xrootd15.cmsaf.mit.edu:1094.0] Closing the socket
[2023-09-05 13:52:00.204969 +0000][Debug  ][PostMaster        ] [xrootd15.cmsaf.mit.edu:1094] Destroying stream
[2023-09-05 13:52:00.204980 +0000][Debug  ][Utility           ] Monitor library name not set. No monitoring
[2023-09-05 13:52:00.204993 +0000][Debug  ][AsyncSock         ] [xrootd15.cmsaf.mit.edu:1094.0] Closing the socket

The text was updated successfully, but these errors were encountered:

amadio · 2023-09-05T19:06:03Z

This is a duplicate of #2078. It will be fixed in release 5.6.2. As a workaround, please use roots:// in your URLs. This bug is caused by commit 8577e1f, which was an attempt at falling back from ZTN (which requires TLS) to other authentication methods when the client doesn't have certificates to be able to use TLS. The patch is such that it doesn't promote root:// URLs to use TLS. The planned fix will require --notlsok to trigger the behavior, so that with default options, the client will behave as before and promote root:// URLs to use TLS (and fail in clients without certificates unless --notlsok is used).

ivmfnal · 2023-09-05T19:19:02Z

Are you sure this is the same issue ?

I am talking about xrdfs ls and stat, not xrdcp.

Where exactly do I use xroots using xrdfs ?

ivmfnal · 2023-09-05T19:22:28Z

Also, sorry for not making this clear earlier. xrdfs ls and stat work fine with some sites but not with others, while all our sites use TLS for client authentication.

Unless --notlsok is explicitly used, the client should try to promote root:// URLs to use TLS. Fixes: xrootd#2078, xrootd#2082, 8577e1f.

amadio · 2023-09-05T19:59:51Z

The patch above should fix this issue, I'd appreciate it if you could test it. Thank you!

amadio · 2023-09-05T20:12:46Z

Note that the original discussions on why the change that caused this issue was needed are in #2020 and #2031.

ivmfnal · 2023-09-05T23:23:18Z

The patch above should fix this issue, I'd appreciate it if you could test it. Thank you!

Are there building instructions ?

amadio · 2023-09-06T03:41:47Z

Yes, in docs/INSTALL.md or I can build RPMs for you and put in a repository on EOS. I'm updating the automation for the DEB/RPM packages, but it's not merged yet, as it's not complete.

ivmfnal · 2023-09-06T09:29:56Z

If you can build it, that would be the best. I appreciate it.

Unless --notlsok is explicitly used, the client should try to promote root:// URLs to use TLS. Fixes: xrootd#2078, xrootd#2082, 8577e1f.

amadio · 2023-09-06T13:35:56Z

Hi, I've built the RPMs. Here's how to install them on a RHEL-based distro (as root):

# dnf install epel-release
# curl -L http://cern.ch/xrootd/xrootd.repo -o /etc/yum.repos.d/xrootd.repo
# dnf install xrootd-client

You will see it as xrootd-client-1:5.6.1.post34+gitb7131e63e-1.el9.x86_64 or similar for your distribution. Please let me know if you have any problems with this. Once I automate our releases, the repositories defined in this xrootd.repo file will be populated with new RPMs which you can then get as updates. Cheers,

ivmfnal · 2023-09-06T14:32:52Z

Works fine. Thanks a lot Guilherme !
When do you plan the next release where this patch will be included ?

amadio · 2023-09-06T15:00:21Z

The release will come early next week, I think (due to holidays and incoming fixes for some HTTP issues). I will merge the changes into devel then. Thank you for testing!

ivmfnal · 2023-09-14T14:48:58Z

Is the new release available yet ?

amadio · 2023-09-14T15:08:28Z

No, tomorrow, sorry. Was waiting for #2072 to be ready for merging.

ivmfnal · 2023-09-14T15:16:57Z

that's fine.

Unless --notlsok is explicitly used, the client should try to promote root:// URLs to use TLS. Fixes: #2078, #2082, 8577e1f.

amadio closed this as completed Sep 5, 2023

amadio added the duplicate label Sep 5, 2023

amadio added a commit to amadio/xrootd that referenced this issue Sep 5, 2023

[XrdCl] Fix promotion of root:// URLs to use TLS encryption

ebf7287

Unless --notlsok is explicitly used, the client should try to promote root:// URLs to use TLS. Fixes: xrootd#2078, xrootd#2082, 8577e1f.

amadio added a commit to amadio/xrootd that referenced this issue Sep 6, 2023

[XrdCl] Fix promotion of root:// URLs to use TLS encryption

849f175

Unless --notlsok is explicitly used, the client should try to promote root:// URLs to use TLS. Fixes: xrootd#2078, xrootd#2082, 8577e1f.

ivmfnal mentioned this issue Sep 6, 2023

Recreate CE pod with newest version of xrootd-client dmwm/CMSRucio#595

Closed

amadio added a commit that referenced this issue Sep 15, 2023

[XrdCl] Fix promotion of root:// URLs to use TLS encryption

47d64a7

Unless --notlsok is explicitly used, the client should try to promote root:// URLs to use TLS. Fixes: #2078, #2082, 8577e1f.

amadio self-assigned this Jan 19, 2024

amadio added this to the 5.6.2 milestone Jan 19, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[FATAL] TLS error: resource temporarily unavailable #2082

[FATAL] TLS error: resource temporarily unavailable #2082

ivmfnal commented Sep 5, 2023

amadio commented Sep 5, 2023

ivmfnal commented Sep 5, 2023

ivmfnal commented Sep 5, 2023

amadio commented Sep 5, 2023

amadio commented Sep 5, 2023

ivmfnal commented Sep 5, 2023

amadio commented Sep 6, 2023

ivmfnal commented Sep 6, 2023

amadio commented Sep 6, 2023

ivmfnal commented Sep 6, 2023

amadio commented Sep 6, 2023

ivmfnal commented Sep 14, 2023

amadio commented Sep 14, 2023

ivmfnal commented Sep 14, 2023

[FATAL] TLS error: resource temporarily unavailable #2082

[FATAL] TLS error: resource temporarily unavailable #2082

Comments

ivmfnal commented Sep 5, 2023

amadio commented Sep 5, 2023

ivmfnal commented Sep 5, 2023

ivmfnal commented Sep 5, 2023

amadio commented Sep 5, 2023

amadio commented Sep 5, 2023

ivmfnal commented Sep 5, 2023

amadio commented Sep 6, 2023

ivmfnal commented Sep 6, 2023

amadio commented Sep 6, 2023

ivmfnal commented Sep 6, 2023

amadio commented Sep 6, 2023

ivmfnal commented Sep 14, 2023

amadio commented Sep 14, 2023

ivmfnal commented Sep 14, 2023