Repository: canonical/operator

Issue:
Log format string missing %s in can_connect
When reviewing some unrelated code, I noticed there was an [invalid `logger.debug` format string](https://github.com/canonical/operator/blob/6ee44cfb64d0680ec7e72ad1c746a87a0c63f0c8/ops/model.py#L1148) in the `model.Container.can_connect` code. It does the following:

```python
logger.debug("Pebble API is not ready; UNIX socket not found:", str(e))
```

However, the logging API expects the first argument to be a format string, so there should be a `%s` here, and the logging library gives this exception (not raised, as logging catches exceptions):

```
>>> logger.debug("Pebble API is not ready; UNIX socket not found:", str(e))
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.9/logging/__init__.py", line 1083, in emit
    msg = self.format(record)
  File "/usr/lib/python3.9/logging/__init__.py", line 927, in format
    return fmt.format(record)
  File "/usr/lib/python3.9/logging/__init__.py", line 663, in format
    record.message = record.getMessage()
  File "/usr/lib/python3.9/logging/__init__.py", line 367, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "<stdin>", line 1, in <module>
Message: 'Pebble API is not ready; UNIX socket not found:'
Arguments: ('REASON',)
```

In addition, when you use `%s`, you don't need `str(e)`, you can just pass `e` directly, and the `%s` formatting calls `str` (which in turn calls `__str__`). We could update the other `APIError` case to omit this too.

I'm not 100% sure, but from a quick glance it looks like `can_connect` is short on tests. We should probably add tests for each exception case and test that it logged something.


Discussion:
benhoyt: @jnsgruk Just noting that if we merge this into main it will be "kept back" for 2.0, as the plan is to release 2.0 from the main branch now (any 1.5.x releases will be done on `1.5-maintenance`). Is that what you intended?
jameinel: sgtm. I'm happy with it landing in main for 2.0.

John
=:->

On Tue, Nov 29, 2022, 17:55 Ben Hoyt ***@***.***> wrote:

> @jnsgruk <https://github.com/jnsgruk> Just noting that if we merge this
> into main it will be "kept back" for 2.0, as the plan is to release 2.0
> from the main branch now (any 1.5.x releases will be done on
> 1.5-maintenance). Is that what you intended?
>
> —
> Reply to this email directly, view it on GitHub
> <https://github.com/canonical/operator/pull/860#issuecomment-1331422892>,
> or unsubscribe
> <https://github.com/notifications/unsubscribe-auth/AABRQ7KVGJZGAIJOWXPO44TWK2CWPANCNFSM6AAAAAASMYFXKA>
> .
> You are receiving this because you commented.Message ID:
> ***@***.***>
>


Patch:
diff --git a/ops/model.py b/ops/model.py
index 9412ae9..79af88f 100644
--- a/ops/model.py
+++ b/ops/model.py
@@ -1418,17 +1418,17 @@ class Container:
             #  instance that is in fact 'ready'.
             self._pebble.get_system_info()
         except pebble.ConnectionError as e:
-            logger.debug("Pebble API is not ready; ConnectionError: %s", e.message())
+            logger.debug("Pebble API is not ready; ConnectionError: %s", e)
             return False
         except FileNotFoundError as e:
             # In some cases, charm authors can attempt to hit the Pebble API before it has had the
             # chance to create the UNIX socket in the shared volume.
-            logger.debug("Pebble API is not ready; UNIX socket not found:", str(e))
+            logger.debug("Pebble API is not ready; UNIX socket not found: %s", e)
             return False
         except pebble.APIError as e:
             # An API error is only raised when the Pebble API returns invalid JSON, or the response
             # cannot be read. Both of these are a likely indicator that something is wrong.
-            logger.warning("Pebble API is not ready; APIError: %s", str(e))
+            logger.warning("Pebble API is not ready; APIError: %s", e)
             return False
         return True
 
diff --git a/ops/pebble.py b/ops/pebble.py
index 71de6fb..0c15c3d 100644
--- a/ops/pebble.py
+++ b/ops/pebble.py
@@ -333,14 +333,6 @@ class Error(Exception):
     def __repr__(self):
         return '<{}.{} {}>'.format(type(self).__module__, type(self).__name__, self.args)
 
-    def name(self):
-        """Return a string representation of the model plus class."""
-        return '<{}.{}>'.format(type(self).__module__, type(self).__name__)
-
-    def message(self):
-        """Return the message passed as an argument."""
-        return self.args[0]
-
 
 class TimeoutError(TimeoutError, Error):
     """Raised when a polling timeout occurs."""


Test patch:
diff --git a/ops/testing.py b/ops/testing.py
index d92609b..98507a5 100755
--- a/ops/testing.py
+++ b/ops/testing.py
@@ -1406,6 +1406,7 @@ class _TestingModelBackend:
         if self._resource_dir is not None:
             self._resource_dir.cleanup()
             self._resource_dir = None
+        self._harness_tmp_dir.cleanup()
 
     def _get_resource_dir(self) -> pathlib.Path:
         if self._resource_dir is None:
diff --git a/test/test_model.py b/test/test_model.py
index 173168f..e1ff14d 100755
--- a/test/test_model.py
+++ b/test/test_model.py
@@ -33,7 +33,14 @@ import ops.testing
 from ops import model
 from ops._private import yaml
 from ops.charm import RelationMeta, RelationRole
-from ops.pebble import APIError, FileInfo, FileType, ServiceInfo
+from ops.pebble import (
+    APIError,
+    ConnectionError,
+    FileInfo,
+    FileType,
+    ServiceInfo,
+    SystemInfo,
+)
 
 
 class TestModel(unittest.TestCase):
@@ -1354,8 +1361,9 @@ containers:
         self.container.replan()
         self.assertEqual(self.pebble.requests, [('replan',)])
 
-    def test_get_system_info(self):
-        self.container.can_connect()
+    def test_can_connect(self):
+        self.pebble.responses.append(SystemInfo.from_dict({'version': '1.0.0'}))
+        self.assertTrue(self.container.can_connect())
         self.assertEqual(self.pebble.requests, [('get_system_info',)])
 
     def test_start(self):
@@ -1687,10 +1695,37 @@ containers:
             ('remove_path', '/path/2', True),
         ])
 
-    def test_bare_can_connect_call(self):
-        self.pebble.responses.append('dummy')
+    def test_can_connect_simple(self):
+        self.pebble.responses.append(SystemInfo.from_dict({'version': '1.0.0'}))
         self.assertTrue(self.container.can_connect())
 
+    def test_can_connect_connection_error(self):
+        def raise_error():
+            raise ConnectionError('connection error!')
+        self.pebble.get_system_info = raise_error
+        with self.assertLogs('ops.model', level='DEBUG') as cm:
+            self.assertFalse(self.container.can_connect())
+        self.assertEqual(len(cm.output), 1)
+        self.assertRegex(cm.output[0], r'DEBUG:ops.model:.*: connection error!')
+
+    def test_can_connect_file_not_found_error(self):
+        def raise_error():
+            raise FileNotFoundError('file not found!')
+        self.pebble.get_system_info = raise_error
+        with self.assertLogs('ops.model', level='DEBUG') as cm:
+            self.assertFalse(self.container.can_connect())
+        self.assertEqual(len(cm.output), 1)
+        self.assertRegex(cm.output[0], r'DEBUG:ops.model:.*: file not found!')
+
+    def test_can_connect_api_error(self):
+        def raise_error():
+            raise APIError('body', 404, 'status', 'api error!')
+        self.pebble.get_system_info = raise_error
+        with self.assertLogs('ops.model') as cm:
+            self.assertFalse(self.container.can_connect())
+        self.assertEqual(len(cm.output), 1)
+        self.assertRegex(cm.output[0], r'WARNING:ops.model:.*: api error!')
+
     def test_exec(self):
         self.pebble.responses.append('fake_exec_process')
         p = self.container.exec(
@@ -1759,6 +1794,7 @@ class MockPebbleClient:
 
     def get_system_info(self):
         self.requests.append(('get_system_info',))
+        return self.responses.pop(0)
 
     def replan_services(self):
         self.requests.append(('replan',))
diff --git a/test/test_pebble.py b/test/test_pebble.py
index 924d110..d076795 100644
--- a/test/test_pebble.py
+++ b/test/test_pebble.py
@@ -1248,7 +1248,7 @@ class TestMultipartParser(unittest.TestCase):
                     if not test.error:
                         self.fail('unexpected error:', err)
                         break
-                    self.assertEqual(test.error, err.message())
+                    self.assertEqual(test.error, str(err))
                 else:
                     if test.error:
                         self.fail('missing expected error: {!r}'.format(test.error))