fix(console): an SSH console tunnel neither stalls on its errors nor hangs on close

ssh's error output went to a pipe that nobody read while the console ran:
once it filled, ssh stopped and the console froze. It now goes to a
temporary file, read when the tunnel closes. Closing waits five seconds
for ssh to end and then kills it, instead of waiting for ever. The Tunnel
holds the ssh process and its error file together.

console/novncd

@@ -21,7 +21,7 @@ django.setup()
 
 from websockify import ProxyRequestHandler, WebSocketProxy  # noqa: E402
 
-from console.sshtunnels import close_tunnel, open_tunnel, tunnel_target  # noqa: E402
+from console.sshtunnels import open_tunnel, tunnel_target  # noqa: E402
 from vrtManager.connection import CONN_SOCKET, CONN_SSH  # noqa: E402
 from webvirtcloud.settings import WS_HOST, WS_PORT  # noqa: E402
 
@@ -140,7 +140,7 @@ class ConsoleClient:
         finally:
             tsock.close()
             if tunnel:
-                error = close_tunnel(tunnel)
+                error = tunnel.close()
                 if error:
                     logging.warning("SSH tunnel to %s@%s failed: %s", connuser, connhost, error)
 

console/sshtunnels.py

@@ -5,6 +5,7 @@ socket on the compute, so the compute needs no nc and runs no shell."""
 import ipaddress
 import socket
 import subprocess
+import tempfile
 
 
 def tunnel_target(address, port, unix_socket):
@@ -21,21 +22,38 @@ def tunnel_target(address, port, unix_socket):
     return f"{address}:{port}"
 
 
+class Tunnel:
+    """The ssh process that carries a console, and its error output, kept in
+    a file: a pipe nobody reads while the console runs would stop ssh once
+    it filled."""
+
+    def __init__(self, argv, sock):
+        self.errors = tempfile.TemporaryFile()
+        self.process = subprocess.Popen(argv, stdin=sock, stdout=sock, stderr=self.errors)
+
+    def close(self):
+        """End ssh, killed if it does not stop within 5 seconds; its error
+        output if it failed, else ""."""
+        if self.process.poll() is None:
+            self.process.terminate()
+        try:
+            self.process.wait(5)
+        except subprocess.TimeoutExpired:
+            self.process.kill()
+            self.process.wait()
+        self.errors.seek(0)
+        error = self.errors.read().decode(errors="replace").strip()
+        self.errors.close()
+        return error if self.process.returncode not in (0, -15) else ""
+
+
 def open_tunnel(host, user, target):
-    """A socket connected to target on host, and the ssh process carrying it.
+    """A socket connected to target on host, and the Tunnel carrying it.
     ssh never asks for anything: a missing key or an unknown host key fails."""
     ours, theirs = socket.socketpair()
     argv = ["ssh", "-o", "BatchMode=yes", "-o", "ConnectTimeout=10", "-W", target]
     if user:
         argv += ["-l", user]
-    process = subprocess.Popen(argv + ["--", host], stdin=theirs, stdout=theirs, stderr=subprocess.PIPE)
+    tunnel = Tunnel(argv + ["--", host], theirs)
     theirs.close()
-    return ours, process
-
-
-def close_tunnel(process):
-    """End the ssh process; its error output, if it failed."""
-    if process.poll() is None:
-        process.terminate()
-    _, error = process.communicate()
-    return error.decode(errors="replace").strip() if process.returncode not in (0, -15) else ""
+    return ours, tunnel

console/tests/test_sshtunnels.py

@@ -2,6 +2,7 @@
 prompt, no remote shell, and its error output when it fails."""
 
 import sys
+import time
 from unittest import TestCase
 from unittest.mock import patch
 
@@ -11,12 +12,12 @@ from console import sshtunnels
 class SshTunnelTests(TestCase):
     def test_ssh_forwards_to_the_console_without_a_shell_or_a_prompt(self):
         with patch.object(sshtunnels.subprocess, "Popen") as popen:
-            sock, process = sshtunnels.open_tunnel("kvm1.example.com", "root", "127.0.0.1:5900")
+            sock, tunnel = sshtunnels.open_tunnel("kvm1.example.com", "root", "127.0.0.1:5900")
         sock.close()
         self.assertEqual(popen.call_args.args[0], [
             "ssh", "-o", "BatchMode=yes", "-o", "ConnectTimeout=10", "-W", "127.0.0.1:5900",
             "-l", "root", "--", "kvm1.example.com"])
-        self.assertIs(process, popen.return_value)
+        self.assertIs(tunnel.process, popen.return_value)
 
     def test_the_target_on_the_compute(self):
         for address, unix_socket, target in (
@@ -31,12 +32,27 @@ class SshTunnelTests(TestCase):
             with self.subTest(address=address, unix_socket=unix_socket):
                 self.assertEqual(sshtunnels.tunnel_target(address, 5900, unix_socket), target)
 
+    def fake_ssh(self, code):
+        """A Tunnel whose process stands in for ssh."""
+        return sshtunnels.Tunnel([sys.executable, "-c", code], None)
+
     def test_a_failed_tunnel_reports_what_ssh_said(self):
-        failing = sshtunnels.subprocess.Popen(
-            [sys.executable, "-c", "import sys; sys.stderr.write('Host key verification failed.'); sys.exit(255)"],
-            stderr=sshtunnels.subprocess.PIPE)
-        failing.wait()  # ssh fails at once, before the session
-        self.assertEqual(sshtunnels.close_tunnel(failing), "Host key verification failed.")
-        ended = sshtunnels.subprocess.Popen([sys.executable, "-c", "import time; time.sleep(30)"],
-                                            stderr=sshtunnels.subprocess.PIPE)
-        self.assertEqual(sshtunnels.close_tunnel(ended), "")  # ended with the session: no error
+        failing = self.fake_ssh("import sys; sys.stderr.write('Host key verification failed.'); sys.exit(255)")
+        failing.process.wait()  # ssh fails at once, before the session
+        self.assertEqual(failing.close(), "Host key verification failed.")
+        ended = self.fake_ssh("import time; time.sleep(30)")
+        self.assertEqual(ended.close(), "")  # ended with the session: no error
+
+    def test_much_error_output_does_not_stop_the_tunnel(self):
+        # a pipe nobody reads stopped the writer at 64 KiB
+        chatty = self.fake_ssh("import sys; sys.stderr.write('x' * 1_000_000); sys.exit(255)")
+        chatty.process.wait(10)
+        self.assertEqual(len(chatty.close()), 1_000_000)
+
+    def test_an_ssh_that_ignores_terminate_is_killed(self):
+        stubborn = self.fake_ssh("import signal, time; signal.signal(signal.SIGTERM, signal.SIG_IGN); time.sleep(60)")
+        time.sleep(1)  # the handler is set
+        started = time.monotonic()
+        stubborn.close()
+        self.assertLess(time.monotonic() - started, 10)
+        self.assertEqual(stubborn.process.returncode, -9)

console/tests/test_views.py

@@ -514,8 +514,7 @@ class NovncdDaemonLogicTestCase(TestCase):
             with self.subTest(console_host=console_host), patch.object(
                 novncd_mod, "get_connection_infos",
                 return_value=("kvm1.example.com", "root", novncd_mod.CONN_SSH, console_host, 5900, console_socket),
-            ), patch.object(novncd_mod, "open_tunnel", return_value=(MagicMock(), MagicMock())) as open_tunnel, \
-                    patch.object(novncd_mod, "close_tunnel", return_value="") as close_tunnel:
+            ), patch.object(novncd_mod, "open_tunnel", return_value=(MagicMock(), MagicMock())) as open_tunnel:
                 handler = self.ConsoleClient()
                 handler.path = "/novncd/?token=1-uuid"
                 handler.msg = MagicMock()
@@ -525,7 +524,7 @@ class NovncdDaemonLogicTestCase(TestCase):
                 open_tunnel.assert_called_once_with("kvm1.example.com", "root", target)
                 socket_factory.assert_not_called()
                 # the tunnel ends with the session
-                close_tunnel.assert_called_once_with(open_tunnel.return_value[1])
+                open_tunnel.return_value[1].close.assert_called_once_with()
 
     def test_a_tcp_hosts_console_is_reached_where_it_listens(self):
         for console_host, reached in (("0.0.0.0", "kvm1.example.com"), ("::", "kvm1.example.com"),