[fix] Enforced command timeout

The SSH library Paramiko was not enforcing the command timeout setting,
a workaround was implemented to ensure the timeout is respected in OpenWISP Controller.

Addresses openwisp/openwisp-firmware-upgrader#244 (comment)

---------

Co-authored-by: Alexandre Vincent <[email protected]>
Co-authored-by: Federico Capoano <[email protected]>

Author: 3 people

openwisp_controller/connection/connectors/exceptions.py

@@ -4,3 +4,11 @@ class CommandFailedException(Exception):
     """
 
     pass
+
+
+class CommandTimeoutException(Exception):
+    """
+    raised when a command times out
+    """
+
+    pass

openwisp_controller/connection/connectors/ssh.py

@@ -1,5 +1,6 @@
 import logging
 import socket
+import time
 from io import BytesIO, StringIO
 
 import paramiko
@@ -10,7 +11,7 @@
 from scp import SCPClient
 
 from .. import settings as app_settings
-from .exceptions import CommandFailedException
+from .exceptions import CommandFailedException, CommandTimeoutException
 
 logger = logging.getLogger(__name__)
 
@@ -148,7 +149,7 @@ def _connect(self, address):
                     auth_timeout=app_settings.SSH_AUTH_TIMEOUT,
                     banner_timeout=app_settings.SSH_BANNER_TIMEOUT,
                     timeout=app_settings.SSH_CONNECTION_TIMEOUT,
-                    **params
+                    **params,
                 )
             except paramiko.ssh_exception.AuthenticationException as e:
                 # the authentication failure may be caused by the issue
@@ -183,9 +184,12 @@ def exec_command(
         - aborts on exceptions
         - raises socket.timeout exceptions
         """
+        # paramiko expects timeout as a float
+        timeout = float(timeout)
         logger.info("Executing command: {0}".format(command))
         # execute commmand
         try:
+            start_cmd = time.perf_counter()
             stdin, stdout, stderr = self.shell.exec_command(command, timeout=timeout)
         # re-raise socket.timeout to avoid being catched
         # by the subsequent `except Exception as e` block
@@ -195,8 +199,16 @@ def exec_command(
         except Exception as e:
             logger.exception(e)
             raise e
-        # store command exit status
-        exit_status = stdout.channel.recv_exit_status()
+        # workaround https://github.com/paramiko/paramiko/issues/1815
+        # workaround https://github.com/paramiko/paramiko/issues/1787
+        # Ref. https://docs.paramiko.org/en/stable/api/channel.html#paramiko.channel.Channel.recv_exit_status  # noqa
+        if not stdout.channel.status_event.wait(
+            timeout=timeout - (time.perf_counter() - start_cmd)
+        ):
+            log_message = f"Command timed out after {timeout} seconds."
+            logger.info(log_message)
+            raise CommandTimeoutException(log_message)
+        exit_status = stdout.channel.exit_status
         # log standard output
         # try to decode to UTF-8, ignoring unconvertible characters
         # https://docs.python.org/3/howto/unicode.html#the-string-type

openwisp_controller/connection/tasks.py

@@ -9,6 +9,7 @@
 from swapper import load_model
 
 from . import settings as app_settings
+from .connectors.exceptions import CommandTimeoutException
 from .exceptions import NoWorkingDeviceConnectionError
 
 logger = logging.getLogger(__name__)
@@ -76,6 +77,10 @@ def launch_command(command_id):
         command.status = "failed"
         command._add_output(_("Background task time limit exceeded."))
         command.save()
+    except CommandTimeoutException as e:
+        command.status = "failed"
+        command._add_output(_(f"The command took longer than expected: {e}"))
+        command.save()
     except Exception as e:
         logger.exception(
             f"An exception was raised while executing command {command_id}"

openwisp_controller/connection/tests/test_models.py

@@ -1,5 +1,6 @@
 import socket
 from unittest import mock
+from unittest.mock import PropertyMock
 
 import paramiko
 from django.contrib.auth.models import ContentType
@@ -46,7 +47,7 @@ def _exec_command_return_value(
         stderr_ = mock.Mock()
         stdin_.read().decode.return_value = stdin
         stdout_.read().decode.return_value = stdout
-        stdout_.channel.recv_exit_status.return_value = exit_code
+        type(stdout_.channel).exit_status = PropertyMock(return_value=exit_code)
         stderr_.read().decode.return_value = stderr
         return (stdin_, stdout_, stderr_)
 
@@ -1009,7 +1010,7 @@ def _assert_applying_conf_test_command(mocked_exec):
                 # 1. Checking openwisp_config returns with 0
                 # 2. Testing presence of /tmp/openwisp/applying_conf returns with 1
                 # 3. Restarting openwisp_config returns with 0 exit code
-                stdout.channel.recv_exit_status.side_effect = [0, 1, 1]
+                type(stdout.channel).exit_status = PropertyMock(side_effect=[0, 1, 1])
                 mocked_exec_command.return_value = (stdin, stdout, stderr)
                 conf.save()
                 self.assertEqual(mocked_exec_command.call_count, 3)

openwisp_controller/connection/tests/test_ssh.py

@@ -70,6 +70,19 @@ def test_connection_failed_command(self, mocked_debug, mocked_info):
             ]
         )
 
+    @mock.patch.object(ssh_logger, "info")
+    @mock.patch.object(ssh_logger, "debug")
+    def test_connection_command_timeout(self, mocked_debug, mocked_info):
+        ckey = self._create_credentials_with_key(port=self.ssh_server.port)
+        dc = self._create_device_connection(credentials=ckey)
+        dc.connector_instance.connect()
+        with self.assertRaises(Exception) as ctx:
+            # timeout of 0.0 is a special case in paramiko -> we check for 0.01 instead
+            dc.connector_instance.exec_command("sleep 1", timeout=0.01)
+        log_message = "Command timed out after 0.01 seconds."
+        mocked_info.assert_has_calls([mock.call(log_message)])
+        self.assertEqual(str(ctx.exception), log_message)
+
     @mock.patch.object(ssh_logger, "info")
     @mock.patch.object(ssh_logger, "debug")
     def test_connection_failed_command_suppressed_output(