feat(logs): a host's connects, failures, closes and refused requests are logged

A run of failed opens is logged once, at its first failure, and the next
successful open ends it; a close callback and a request refused because the
host's requests still wait are logged each time. The lines go to the app log
of the process (web or job worker).

vrtManager/connection.py

@@ -1,6 +1,7 @@
 from django.utils.translation import gettext_noop
 import contextlib
 import io
+import logging
 import os
 import re
 import socket
@@ -56,6 +57,8 @@ CLOSE_REASONS = {
 # in place of ssh and never passes one itself)
 SSH_COMMAND = os.path.join(os.path.dirname(os.path.abspath(__file__)), "libvirt-ssh")
 
+logger = logging.getLogger(__name__)
+
 
 class wvmEventLoop(threading.Thread):
     """ Event Loop Class"""
@@ -136,6 +139,7 @@ def _count_on(connection):
         return
     _leave_host()
     if not connection.requests.acquire(timeout=CONNECT_TIMEOUT):
+        logger.warning("%s: request refused, %s requests still wait for the host", connection.host, HOST_REQUESTS)
         raise util.ConnectionFailed(gettext_noop("Connection Failed: %(host)s does not answer: %(requests)s requests still wait for it"),
                                     host=connection.host, requests=HOST_REQUESTS)
     _request.held = connection
@@ -178,6 +182,7 @@ class wvmConnection(object):
         self.last_error = None
         self._opening = None  # threading.Event of the open in progress
         self._retry_at = 0.0  # monotonic time before which no new open is tried
+        self._failing = False  # the last open failed: its failure is logged, the next ones are not
         self.requests = None  # the web requests using the host (HOST_REQUESTS), set by the manager
 
         # credentials
@@ -210,6 +215,7 @@ class wvmConnection(object):
                     self.last_error = util.message(gettext_noop("Connection Failed: %(host)s did not answer within %(seconds)s s"),
                                                    host=self.host, seconds=CONNECT_TIMEOUT)
                     opening.abandoned = True
+                    self._log_failure()
 
     def _open(self, opening):
         """Helper thread: open, configure and publish the connection."""
@@ -237,13 +243,22 @@ class wvmConnection(object):
                     self.connection = connection
                     self.last_error = None
                     self._retry_at = 0.0
+                    self._failing = False
+                    logger.info("%s: connected", self.host)
                 else:
                     self.connection = None
                     self.last_error = error
                     self._retry_at = time.monotonic() + RETRY_AFTER
+                    self._log_failure()
                 self._opening = None
             opening.set()
 
+    def _log_failure(self):
+        """Log last_error if it starts a run of failures (the caller holds connection_state_lock)."""
+        if not self._failing:
+            self._failing = True
+            logger.warning("%s: %s", self.host, util.render(self.last_error["text"], self.last_error["values"], str))
+
     def _open_transport(self):
         if self.type == CONN_TCP:
             return self.__connect_tcp()
@@ -293,6 +308,7 @@ class wvmConnection(object):
                 self.last_error = util.message(gettext_noop("Connection closed (%(reason)s)"), reason=reason)
             # prevent other threads from using the connection (in the future)
             self.connection = None
+            logger.warning("%s: %s", self.host, util.render(self.last_error["text"], self.last_error["values"], str))
 
     def __connect_tcp(self):
         flags = [libvirt.VIR_CRED_AUTHNAME, libvirt.VIR_CRED_PASSPHRASE]

vrtManager/tests/test_connection.py

@@ -197,6 +197,26 @@ class BoundedOpenTestCase(unittest.TestCase):
         self.assertIsNone(entry.connection)
         self.assertEqual(entry.last_error, {"text": "Connection closed (keepalive timeout)", "values": {}})
 
+    def test_the_log_has_each_change_of_a_host_not_each_retry(self):
+        self.release.set()
+        conn = alive_connection()
+        with self.assertLogs("vrtManager.connection") as logs:
+            with self.open_auth(libvirt.libvirtError("refused")):
+                self.get()
+                entry = self.manager._search_connection("h", "u", "p", CONN_TCP)
+                entry._retry_at = 0.0  # RETRY_AFTER is over
+                self.get()
+            entry._retry_at = 0.0
+            with self.open_auth(conn):
+                self.get()
+            entry._wvmConnection__connection_close_callback(conn, 2)
+        self.assertEqual(self.calls, 3)
+        self.assertEqual(logs.output, [
+            "WARNING:vrtManager.connection:h: Connection Failed: refused",
+            "INFO:vrtManager.connection:h: connected",
+            "WARNING:vrtManager.connection:h: Connection closed (keepalive timeout)",
+        ])
+
     def test_a_connection_closed_before_it_is_published_is_an_error(self):
         self.release.set()
         dead = alive_connection()
@@ -264,8 +284,10 @@ class HostRequestsTestCase(unittest.TestCase):
     def test_a_third_request_to_a_host_is_refused_and_other_hosts_answer(self):
         self.assertEqual(self.request("h") + self.request("h"), [])
         started = time.monotonic()
-        self.assertEqual(self.request("h"), ["Connection Failed: h does not answer: 2 requests still wait for it"])
+        with self.assertLogs("vrtManager.connection", "WARNING") as logs:
+            self.assertEqual(self.request("h"), ["Connection Failed: h does not answer: 2 requests still wait for it"])
         self.assertGreaterEqual(time.monotonic() - started, 0.2)
+        self.assertEqual(logs.output, ["WARNING:vrtManager.connection:h: request refused, 2 requests still wait for the host"])
         self.assertEqual(self.request("g"), [])
 
     def test_a_host_counts_its_requests_whatever_the_login(self):