Segmentation fault and ssl errors after the client connection is cut by KeyboardInterrupt

[mstfdkmn]

When downloading a relatively large file, interrupting the connection after 10-15 seconds with a keyboard interrupt (Ctrl+C) results in SSL errors. A second interrupt is needed to stop the hang. This second interrupt then leads to a segmentation fault.

my prc script:

[irods@dev-u0137480 irods]$ cat test.py
env_file = os.getenv('IRODS_ENVIRONMENT_FILE', os.path.expanduser('~/.irods/irods_environment.json'))
with iRODSSession(irods_env_file=env_file) as session:
    session.data_objects.get("/u0137480/home/rods/10G.img", "10G.img")

[irods@dev-u0137480 irods]$ python3 test.py
^CCRITICAL:irods.connection:TLS/SSL connection has been closed (EOF) (_ssl.c:2651)
ERROR:irods.connection:Could not receive server response
Traceback (most recent call last):
  File "/etc/irods/test.py", line 8, in <module>
    session.data_objects.get("/u0137480/home/rods/10G.img", "10G.img")
  File "/usr/local/lib/python3.9/site-packages/irods/manager/data_object_manager.py", line 280, in get
    self._download(
  File "/usr/local/lib/python3.9/site-packages/irods/manager/data_object_manager.py", line 248, in _download
    if not self.parallel_get(
  File "/usr/local/lib/python3.9/site-packages/irods/manager/data_object_manager.py", line 419, in parallel_get
    return parallel.io_main(
  File "/usr/local/lib/python3.9/site-packages/irods/parallel.py", line 543, in io_main
    retval = _io_multipart_threaded(
  File "/usr/local/lib/python3.9/site-packages/irods/parallel.py", line 447, in _io_multipart_threaded
    bytecounts = [f.result() for f in futures]
  File "/usr/local/lib/python3.9/site-packages/irods/parallel.py", line 447, in <listcomp>
    bytecounts = [f.result() for f in futures]
  File "/usr/lib64/python3.9/concurrent/futures/_base.py", line 441, in result
    self._condition.wait(timeout)
  File "/usr/lib64/python3.9/threading.py", line 312, in wait
    waiter.acquire()
KeyboardInterrupt

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/etc/irods/test.py", line 8, in <module>
    session.data_objects.get("/u0137480/home/rods/10G.img", "10G.img")
  File "/usr/local/lib/python3.9/site-packages/irods/session.py", line 197, in __exit__
    self.cleanup()
  File "/usr/local/lib/python3.9/site-packages/irods/session.py", line 243, in cleanup
    conn.disconnect()
  File "/usr/local/lib/python3.9/site-packages/irods/connection.py", line 379, in disconnect
    self.socket = self.socket.unwrap()
  File "/usr/lib64/python3.9/ssl.py", line 1319, in unwrap
    s = self._sslobj.shutdown()
ssl.SSLError: [SSL] record layer failure (_ssl.c:2774)
^CException ignored in: <module 'threading' from '/usr/lib64/python3.9/threading.py'>
Traceback (most recent call last):
  File "/usr/lib64/python3.9/threading.py", line 1447, in _shutdown
    atexit_call()
  File "/usr/lib64/python3.9/concurrent/futures/thread.py", line 31, in _python_exit
    t.join()
  File "/usr/lib64/python3.9/threading.py", line 1060, in join
    self._wait_for_tstate_lock()
  File "/usr/lib64/python3.9/threading.py", line 1080, in _wait_for_tstate_lock
    if lock.acquire(block, timeout):
KeyboardInterrupt:
Segmentation fault (core dumped)

irods logs:

{"processname": "irods", "groupname": "irods", "pid": "147", "channel": "stdout", "irods": {"log_category": "agent_factory", "log_level": "error", "log_message": "Agent process [11186] exited with status [1].", "server_host": "dev-u0137480.irods.t.icts.kuleuven.be", "server_pid": 176, "server_timestamp": "2025-05-07T12:36:41.824Z", "server_type": "agent_factory", "server_zone": "u0137480"}}
{"processname": "irods", "groupname": "irods", "pid": "147", "channel": "stdout", "irods": {"log_category": "agent", "log_level": "error", "log_message": "[-]\t/irods_source/server/core/src/rodsAgent.cpp:677:int runIrodsAgentFactory(sockaddr_un) :  status [SYS_HEADER_TYPE_LEN_ERR]  errno [] -- message [wrong message type [RODS_DISCONNECT] expected [RODS_CS_NEG_T]]\n\t[-]\t/irods_source/server/core/src/irods_server_negotiation.cpp:141:irods::error irods::client_server_negotiation_for_server(irods::network_object_ptr, std::string &) :  status [SYS_HEADER_TYPE_LEN_ERR]  errno [] -- message [wrong message type [RODS_DISCONNECT] expected [RODS_CS_NEG_T]]\n\t\t[-]\t/irods_source/lib/core/src/irods_client_negotiation.cpp:523:irods::error irods::read_client_server_negotiation_message(irods::network_object_ptr, boost::shared_ptr<cs_neg_t> &) :  status [SYS_HEADER_TYPE_LEN_ERR]  errno [] -- message [wrong message type [RODS_DISCONNECT] expected [RODS_CS_NEG_T]]\n\n", "server_host": "dev-u0137480.irods.t.icts.kuleuven.be", "server_pid": 11405, "server_timestamp": "2025-05-07T12:36:53.698Z", "server_type": "agent", "server_zone": "u0137480"}}
{"processname": "irods", "groupname": "irods", "pid": "147", "channel": "stdout", "irods": {"log_category": "agent_factory", "log_level": "error", "log_message": "Agent process [11405] exited with status [1].", "server_host": "dev-u0137480.irods.t.icts.kuleuven.be", "server_pid": 176, "server_timestamp": "2025-05-07T12:36:53.723Z", "server_type": "agent_factory", "server_zone": "u0137480"}}
{"processname": "irods", "groupname": "irods", "pid": "147", "channel": "stdout", "irods": {"log_category": "legacy", "log_level": "error", "log_message": "[-]\t/irods_source/server/core/src/rsApiHandler.cpp:565:int readAndProcClientMsg(rsComm_t *, int) :  status [SYS_HEADER_READ_LEN_ERR]  errno [] -- message [failed to call 'read header']\n\t[-]\t/irods_source/lib/core/src/sockComm.cpp:229:irods::error readMsgHeader(irods::network_object_ptr, msgHeader_t *, struct timeval *) :  status [SYS_HEADER_READ_LEN_ERR]  errno [] -- message [failed to call 'read header']\n\t\t[-]\t/irods_source/plugins/network/src/ssl.cpp:528:irods::error ssl_read_msg_header(irods::plugin_context &, void *, struct timeval *) :  status [SYS_HEADER_READ_LEN_ERR]  errno [] -- message [read 0 expected 4]\n\n", "request_api_name": "DATA_OBJ_LSEEK_AN", "request_api_number": 674, "request_api_version": "d", "request_client_user": "rods", "request_host": "10.0.2.100", "request_proxy_user": "rods", "request_release_version": "rods4.3.4", "server_host": "dev-u0137480.irods.t.icts.kuleuven.be", "server_pid": 12181, "server_timestamp": "2025-05-07T12:38:25.548Z", "server_type": "agent", "server_zone": "u0137480"}}
{"processname": "irods", "groupname": "irods", "pid": "147", "channel": "stdout", "irods": {"log_category": "agent", "log_level": "error", "log_message": "[-]\t/irods_source/server/core/src/rodsAgent.cpp:728:int runIrodsAgentFactory(sockaddr_un) :  status [SSL_SHUTDOWN_ERROR]  errno [] -- message [failed to call 'agent stop']\n\t[-]\t/irods_source/lib/core/src/sockComm.cpp:191:irods::error sockAgentStop(irods::network_object_ptr) :  status [SSL_SHUTDOWN_ERROR]  errno [] -- message [failed to call 'agent stop']\n\t\t[-]\t/irods_source/plugins/network/src/ssl.cpp:850:irods::error ssl_agent_stop(irods::plugin_context &) :  status [SSL_SHUTDOWN_ERROR]  errno [] -- message [error completing shutdown of SSL connection | error:0A000438:SSL routines::tlsv1 alert internal error | error:0A000197:SSL routines::shutdown while in init]\n\n", "request_api_name": "DATA_OBJ_LSEEK_AN", "request_api_number": 674, "request_api_version": "d", "request_client_user": "rods", "request_host": "10.0.2.100", "request_proxy_user": "rods", "request_release_version": "rods4.3.4", "server_host": "dev-u0137480.irods.t.icts.kuleuven.be", "server_pid": 12181, "server_timestamp": "2025-05-07T12:38:25.548Z", "server_type": "agent", "server_zone": "u0137480"}}
{"processname": "irods", "groupname": "irods", "pid": "147", "channel": "stdout", "irods": {"log_category": "server", "log_level": "critical", "log_message": "Agent factory returned with error code [-2104000].", "request_api_name": "DATA_OBJ_LSEEK_AN", "request_api_number": 674, "request_api_version": "d", "request_client_user": "rods", "request_host": "10.0.2.100", "request_proxy_user": "rods", "request_release_version": "rods4.3.4", "server_host": "dev-u0137480.irods.t.icts.kuleuven.be", "server_pid": 12181, "server_timestamp": "2025-05-07T12:38:25.551Z", "server_type": "agent", "server_zone": "u0137480"}}
{"processname": "irods", "groupname": "irods", "pid": "147", "channel": "stdout", "irods": {"log_category": "agent_factory", "log_level": "error", "log_message": "Agent process [12181] exited with status [1].", "server_host": "dev-u0137480.irods.t.icts.kuleuven.be", "server_pid": 176, "server_timestamp": "2025-05-07T12:38:25.567Z", "server_type": "agent_factory", "server_zone": "u0137480"}}
{"processname": "irods", "groupname": "irods", "pid": "147", "channel": "stdout", "irods": {"log_category": "agent", "log_level": "error", "log_message": "[-]\t/irods_source/server/core/src/rodsAgent.cpp:728:int runIrodsAgentFactory(sockaddr_un) :  status [SSL_SHUTDOWN_ERROR]  errno [] -- message [failed to call 'agent stop']\n\t[-]\t/irods_source/lib/core/src/sockComm.cpp:191:irods::error sockAgentStop(irods::network_object_ptr) :  status [SSL_SHUTDOWN_ERROR]  errno [] -- message [failed to call 'agent stop']\n\t\t[-]\t/irods_source/plugins/network/src/ssl.cpp:850:irods::error ssl_agent_stop(irods::plugin_context &) :  status [SSL_SHUTDOWN_ERROR]  errno [] -- message [error completing shutdown of SSL connection | error:0A000123:SSL routines::application data after close notify]\n\n", "request_api_name": "DATA_OBJ_CLOSE_AN", "request_api_number": 673, "request_api_version": "d", "request_client_user": "rods", "request_host": "10.0.2.100", "request_proxy_user": "rods", "request_release_version": "rods4.3.4", "server_host": "dev-u0137480.irods.t.icts.kuleuven.be", "server_pid": 12642, "server_timestamp": "2025-05-07T12:39:06.365Z", "server_type": "agent", "server_zone": "u0137480"}}
{"processname": "irods", "groupname": "irods", "pid": "147", "channel": "stdout", "irods": {"log_category": "server", "log_level": "critical", "log_message": "Agent factory returned with error code [-2104000].", "request_api_name": "DATA_OBJ_CLOSE_AN", "request_api_number": 673, "request_api_version": "d", "request_client_user": "rods", "request_host": "10.0.2.100", "request_proxy_user": "rods", "request_release_version": "rods4.3.4", "server_host": "dev-u0137480.irods.t.icts.kuleuven.be", "server_pid": 12642, "server_timestamp": "2025-05-07T12:39:06.368Z", "server_type": "agent", "server_zone": "u0137480"}}
{"processname": "irods", "groupname": "irods", "pid": "147", "channel": "stdout", "irods": {"log_category": "agent_factory", "log_level": "error", "log_message": "Agent process [12642] exited with status [1].", "server_host": "dev-u0137480.irods.t.icts.kuleuven.be", "server_pid": 176, "server_timestamp": "2025-05-07T12:39:06.385Z", "server_type": "agent_factory", "server_zone": "u0137480"}}

Also, different connection interruption times may show other errors. To reproduce the SSL/segmentation fault, I typically interrupt 10-15 seconds after script execution.

[d-w-moore]

The segfault is a surprise, as I haven't seen Python3.9 do that up to now....
Admittedly the per thread wind-up logic could be tightened up. (Too many mutexes in use?)

Alternatively we could set the auxiliary transfer threads to a daemonic status.

I have read that in Python 3.9+, the developers of the concurrent module don't like daemon threads anymore due to problems with the new feature of subinterpreters.

[d-w-moore]

I have read that in Python 3.9+, the developers of the concurrent module don't like daemon threads anymore due to problems with the new feature of subinterpreters.

confirmed:

$ python3 -c 'import sys, irods.helpers as h; print (f"{sys.version=}"); s=h.make_session();s.data_objects.get("/tempZone/home/rods/big.dat","big")'
sys.version='3.8.10 (default, Nov 22 2023, 10:22:35) \n[GCC 9.4.0]'
 *** threading.current_thread().daemon = True
 *** threading.current_thread().daemon = True
 *** threading.current_thread().daemon = True
$ . py3*venv/bin/activate
(py3.9.15-venv)$ rm big
(py3.9.15-venv)$ python3 -c 'import sys, irods.helpers as h; print (f"{sys.version=}"); s=h.make_session();s.data_objects.get("/tempZone/home/rods/big.dat","big")'
sys.version='3.9.15 (main, May  7 2025, 14:32:44) \n[GCC 9.4.0]'
 *** threading.current_thread().daemon = False
 *** threading.current_thread().daemon = False
 *** threading.current_thread().daemon = False
 $ 

[korydraughn]

What does that code snippet tell us?

[d-w-moore]

What does that code snippet tell us?

It's a confirmation that threads generated by concurrent.futures have switched to using non daemonized threads in python 3.9 and later. That's why in those versions the Prc hangs on control c

[d-w-moore]

I'd assume the subordinate threads carrying on after the main thread has cleaned up its connections is part of the problem. But i haven't confirmed that....

[d-w-moore]

A possible solution (in some future release of the Python iRODS Client, in which we've added support for what I'm proposing) would be for the app programmer to intercept the SIGINT (and also SIGTERM). The handler for that signal would effects an abort() on the synchronizing Barrier object that underlies the various threads of any/all ongoing instances of data object parallel transfer.

[d-w-moore]

A possible solution (in some future release of the Python iRODS Client, in which we've added support for what I'm proposing) would be for the app programmer to intercept the SIGINT (and also SIGTERM). The handler for that signal would effects an abort() on the synchronizing Barrier object that underlies the various threads of any/all ongoing instances of data object parallel transfer.

OK. Better even than that: what we should do probably is trap KeyboardInterrupt in irods.parallel.io_main, and in the exception catch logic, abort the Barrier object of the various transfer threads right there. If any AsyncNotify objects are still actively transferring in the background of an application (kind of a niche feature anyway) , we can supply a free function that similarly aborts all existing client/server data transfer threads, and make it the user's option to implement a signal handler to call that free function.

[d-w-moore]

@mstfdkmn - I was able to reproduce the hanging behavior, but not the segmentation fault, even under Python 3.9. If you have any extra information about the exact Python version (I know it's 3.9.X) you were using, or any other possibly relevant details, maybe you could share. Otherwise, though, even without my seeing the seg fault, I believe there is a strong possibility this PR (in its present state) could address the problem.

[alanking]

See #728

[mstfdkmn]

@mstfdkmn - I was able to reproduce the hanging behavior, but not the segmentation fault, even under Python 3.9. If you have any extra information about the exact Python version (I know it's 3.9.X) you were using, or any other possibly relevant details, maybe you could share. Otherwise, though, even without my seeing the seg fault, I believe there is a strong possibility this PR in its present state, could address the problem in its entirety.

Ok thanks, I will be able to look at this later. But I think that I was getting the segfault error after I kept trying continuously to be able to capture it in correct moment.

[mstfdkmn]

The python version that I reproduce the issue with is Python 3.9.21. To be able to produce this, I think you need to try several times without waiting.

An I see the following in irods log just after I encounter segfault:

{"processname": "rsyslogd", "groupname": "rsyslogd", "pid": "135", "channel": "stdout", "rsyslogd": {"log_category": "agent", "log_level": "error", "log_message": "[-]\t/irods_source/server/main_server/src/agent_main.cpp:965:int (anonymous namespace)::handle_client_request(int, std::time_t) : status [SSL_SHUTDOWN_ERROR] errno [] -- message [failed to call 'agent stop']\n\t[-]\t/irods_source/lib/core/src/sockComm.cpp:181:irods::error sockAgentStop(irods::network_object_ptr) : status [SSL_SHUTDOWN_ERROR] errno [] -- message [failed to call 'agent stop']\n\t\t[-]\t/irods_source/plugins/network/src/ssl.cpp:787:irods::error ssl_agent_stop(irods::plugin_context &) : status [SSL_SHUTDOWN_ERROR] errno [] -- message [error completing shutdown of SSL connection | error:0A000126:SSL routines::unexpected eof while reading | error:0A000197:SSL routines::shutdown while in init]\n\n", "request_api_name": "DATA_OBJ_CLOSE_AN", "request_api_number": 673, "request_api_version": "d", "request_client_user": "rods", "request_host": "10.0.2.100", "request_proxy_user": "rods", "request_release_version": "rods4.3.4", "server_host": "dev-u0137480.irods.t.icts.kuleuven.be", "server_pid": 321927, "server_timestamp": "2025-06-02T11:56:40.970Z", "server_type": "agent", "server_zone": "u0137480"}}