diff --git a/vrtManager/connection.py b/vrtManager/connection.py index 8689cfbb..6c430419 100644 --- a/vrtManager/connection.py +++ b/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] diff --git a/vrtManager/tests/test_connection.py b/vrtManager/tests/test_connection.py index f1eed0c8..c876d128 100644 --- a/vrtManager/tests/test_connection.py +++ b/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):