Repository: canonical/operator
Pull request #1155 (2024-03-20 09:45:47)

fix(pebble): catch socket.timeout exception in pebble.Client.exec()
Tried to run some `container.exec` in a test charm with sleep, with some other long-running commands like apt-update, with or without timeout, but could not reproduce the issue.

Changed according to John's opinion: catch `socket.timeout` exception and continue polling till the end of the deadline.

Also updated docstring for `model.Container.exec()` and `pebble.Client.exec()`.

Closes https://github.com/canonical/operator/issues/826.



IronCore864: > There are also some other issues raised in #826 that I think we should either comment on somewhere (there or in this PR) or adjust. In particular:
> 
> 1. The Unix socket has code for providing a timeout, but I don't think there's any way for a charm (or even the Pebble client) to provide that, so it's unclear why it's there. Am I missing some way that it can be set, or some reason to provide it even though it's never used?
> 2. The Pebble client has a timeout that's used for (I think) everything other than `exec`, but Charm's basically can't use this, because it's not exposed to the model. Is that deliberate? Should a charm be able to change this timeout?
> 3. It seems like in the original report that the timeout was happening after ~13s, but it should presumably have been 5s. Have we checked that we do see a timeout after 5s and not a longer time?

To answer the 3rd question first, [the 5s timeout](https://github.com/canonical/operator/blob/main/ops/pebble.py#L1732) is `pebble.Client.timeout`, and as John mentioned in the issue, the intent for it is "If we have sent a request to pebble, and it hasn't responded within 5s, loop around again and poll some more."

It's not the timeout for executing the command created by `Container.exec().wait()`. If we run `container.exec(["sleep", "60"]).wait()` without a timeout, [it will run for 60s](https://github.com/canonical/operator/blob/main/ops/pebble.py#L2023) for sure. The way to set timeout for the actual command is `container.exec(["sleep", "60"], timeout=3).wait()`, and this will throw some exception like `ops.pebble.ChangeError: cannot perform the following tasks: exec command "sleep" (timed out after 3s: context deadline exceeded)`.

The code in the original issue doesn't set timeout for `exec` and is waiting forever, but `socket.timeout` is raised, that is why we added `except socket.timeout`. As for why it's 13 seconds, I'm not sure, seems weird, and I could not reproduce `socket.timeout`.

---

[John did mention that](https://github.com/canonical/operator/issues/826#issuecomment-1239540051) the 5s timeout to pebble can't be configured and I checked, it's true, it can't be set in the entire OF code:

When creating a model, [metadata is used](https://github.com/canonical/operator/blob/main/ops/main.py#L410), then passed to Unit, which is [created by model](https://github.com/canonical/operator/blob/main/ops/model.py#L118), [using _ModelCache](https://github.com/canonical/operator/blob/main/ops/model.py#L325). Then [unit creates containers](https://github.com/canonical/operator/blob/main/ops/model.py#L514), [container initializes pebble client](https://github.com/canonical/operator/blob/8097cca861eae31727636f92c932738d14d0ac81/ops/model.py#L2094). However, no where in the whole chain is pebble timeout set, so it's always the default 5s.

I think if we want to expose pebble timeout as a configuration item, one way to do so is to add something like `pebble-timeout` in `[ContainerMeta](https://github.com/canonical/operator/blob/main/ops/charm.py#L1688)` and tweak [the code where it creates containers](https://github.com/canonical/operator/blob/8097cca861eae31727636f92c932738d14d0ac81/ops/model.py#L514), so that charmers can set pebble timeout in `charmcraft.yaml`, containers section.

I don't know if this change is worth it, because A, 5s seems to be an OK value, and B, users probably only care about `container.exec(timeout=xxx)` which is supported, I don't know why they want to tweak the pebble timeout.

Is it worth adding this feature? Need your input here @benhoyt @tonyandrewmeyer.

---

Another thing John mentioned was [the `_UnixSocketConnection` timeout](https://github.com/canonical/operator/issues/826#issuecomment-1239542298) issue that we set it even if charmers don't ask for it explicity, but I don't think it's true anymore, [we only set it if it's provided](https://github.com/canonical/operator/blob/main/ops/pebble.py#L321). Should we comment in the issue?
tonyandrewmeyer: > To answer the 3rd question first, [the 5s timeout](https://github.com/canonical/operator/blob/main/ops/pebble.py#L1732) is `pebble.Client.timeout`, and as John mentioned in the issue, the intent for it is "If we have sent a request to pebble, and it hasn't responded within 5s, loop around again and poll some more."

This is badly named, in my opinion, but we can't do anything about that now. 

If I understand correctly, if I do `Client(timeout=5).autostart_services(timeout=30)`, then:

* A request is sent to Pebble, with a timeout of 5s saying "do this change"
* A request is sent to Pebble, with a timeout of 5s saying "wait for that change to finish" - this also sends a timeout of 4s to Pebble's wait API. If the request gives a 503, then we try again (until we have used up 30s waiting for the change to happen, in which case we raise `TimeoutError` - the last attempt might wait less than 4s if there isn't that much left to get to 30s), otherwise we raise an `APIError`.

The wait API is a bit odd in that we are basically polling, but it seems to have been added to avoid polling.

If I do `Client(timeout=5).exec(timeout=30, ...)` then:

* A request is sent to Pebble, with a timeout of 5s saying "run this command" and that includes the 30s timeout as a parameter for Pebble's context.
* (Bunch of websocket stuff for handling I/O)
* A request is sent to Pebble, with a timeout of 5s saying "wait for that command to finish" - this also sends a timeout of 4s to Pebble's wait API. If the request gives a 503, then we try again (until we have used up 31s waiting for the change to happen, in which case we raise `TimeoutError` - the last attempt might wait less than 4s if there isn't that much left to get to 30s), otherwise we raise an `APIError`.

So they are basically the same underneath.

> It's not the timeout for executing the command created by `Container.exec().wait()`. If we run `container.exec(["sleep", "60"]).wait()` without a timeout, [it will run for 60s](https://github.com/canonical/operator/blob/main/ops/pebble.py#L2023) for sure.

Yeah, I get that there are a bunch of different timeouts here, the `pebble.Client.timeout` is mostly an implementation detail around how granular the timeout checks are, and the methods that are expected to be slow (`exec`, `autostart_services`, `restart_services`, etc) all have their own timeout that's passed when they are run (and that's a timeout waiting for Pebble to do whatever you've asked).

Although the ticket summary is about the leaked exception, I think the broader problem (of the two issues combined) is "Pebble timeouts are confusing", and it'd be good to solve that, rather than just the specific leaking exception.

> As for why it's 13 seconds, I'm not sure, seems weird, and I could not reproduce `socket.timeout`.

I would guess that the 13 comes from three attempts - we tried 2 times to get the change result from Pebble, waiting 4s each time, and that all worked as designed, and then on the 3rd attempt instead of the Pebble call timing out, the socket connection timed out after 5s (4+4+5=13).

If so I guess this is fine, because now we'll be catching that socket error and it'll time out after 30s.

> I think if we want to expose pebble timeout as a configuration item,

I think we probably do *not* want to expose this, since it's not what users would think of a timeout. I think we do want to explain in the `pebble.Client` docs what that `timeout` attribute actually is.

> Another thing John mentioned was [the `_UnixSocketConnection` timeout](https://github.com/canonical/operator/issues/826#issuecomment-1239542298) issue that we set it even if charmers don't ask for it explicity, but I don't think it's true anymore, [we only set it if it's provided](https://github.com/canonical/operator/blob/main/ops/pebble.py#L321). Should we comment in the issue?

I looked at this a bit more closely and it's clearer to me now. `_UnixSocketConnection` takes the `timeout` argument because it's a subclass of `http.client.HTTPConnection`, and that has a `timeout` argument. We do set the UNIX socket to use this timeout (but do it later than we should - you're really meant to set it before `connect()`). It's passed to `_UnixSocketConnection` via the `urllib.request` handling mechanism (that's how the 5s value gets everywhere), so it is always set by Pebble.
IronCore864: I agree that "Pebble timeouts are confusing" -- at least this is what I was thinking when I was reading the code.

I think it's too complicated to be completely refactored, also I don't know what the impact circle would be. Still, maybe we can do some minimal refactoring to make it better, even just slightly so?

Off the top of my head, I have the following ideas:

1. Remove `timeout: float = 5.0` from `pebble.Client.__init__()` because it's not configurable anyway. Make it a hard-coded constant value.
2. Rename `pebble.Client.timeout` to something more meaningful, maybe `pebble.Client.connection_timeout` or `pebble.Client.socket_timeout`, to make it clear that it's not "the timeout for executing a command in the container". I think this parameter is used for [`urllib.request.OpenerDirector.open`](https://docs.python.org/3/library/urllib.request.html#urllib.request.OpenerDirector.open), which says "The optional timeout parameter specifies a timeout in seconds for blocking operations like the connection attempt." So I think maybe `pebble.Client.connection_timeout` is a better name to be consistent with `urllib.request`?
3. Refactor the `_wait_change_using_wait` method a bit to make it more readable.


IronCore864: > This is badly named, in my opinion, but we can't do anything about that now.
> 
> Although the ticket summary is about the leaked exception, I think the broader problem (of the two issues combined) is "Pebble timeouts are confusing", and it'd be good to solve that, rather than just the specific leaking exception.

I agree that "Pebble timeouts are confusing" -- at least this is what I was thinking when I was reading the code.

I think it's too complicated to be completely refactored, also I don't know what the impact circle would be. Still, maybe we can do some minimal refactoring to make it better, even just slightly so?

Off the top of my head, I have the following ideas:

1. Remove `timeout: float = 5.0` from `pebble.Client.__init__()` because it's not configurable anyway. Make it a hard-coded constant value.
2. Rename `pebble.Client.timeout` to something more meaningful, maybe `pebble.Client.connection_timeout` or `pebble.Client.socket_timeout`, to make it clear that it's not "the timeout for executing a command in the container". I think this parameter is used for [`urllib.request.OpenerDirector.open`](https://docs.python.org/3/library/urllib.request.html#urllib.request.OpenerDirector.open), which says "The optional timeout parameter specifies a timeout in seconds for blocking operations like the connection attempt." So I think maybe `pebble.Client.connection_timeout` is a better name to be consistent with `urllib.request`?
3. Refactor the `_wait_change_using_wait` method a bit to make it more readable.


tonyandrewmeyer: > 1. Remove `timeout: float = 5.0` from `pebble.Client.__init__()` because it's not configurable anyway. Make it a hard-coded constant value.

Even though this isn't accessible directly by charms, this would break backwards compatibility so we can't really do it. I don't think there's much we can do other than make the documentation clearer on what this value is (unless we do want to expose it to charms, but as we discussed above, I don't think so).

> 2. Rename `pebble.Client.timeout` to something more meaningful, maybe `pebble.Client.connection_timeout` or `pebble.Client.socket_timeout`, to make it clear that it's not "the timeout for executing a command in the container". I think this parameter is used for [`urllib.request.OpenerDirector.open`](https://docs.python.org/3/library/urllib.request.html#urllib.request.OpenerDirector.open), which says "The optional timeout parameter specifies a timeout in seconds for blocking operations like the connection attempt." So I think maybe `pebble.Client.connection_timeout` is a better name to be consistent with `urllib.request`?

I think a different name would have been great, but this would again break backwards compatibility, so we can't really do it (in ops 2.x).
benhoyt: Yeah, and can see how the "Client.timeout" name is confusing. I agree with Tony's assessment above:

> > I think if we want to expose pebble timeout as a configuration item,

> I think we probably do not want to expose this, since it's not what users would think of a timeout. I think we do want to explain in the pebble.Client docs what that timeout attribute actually is.

I don't think we should expose the ability for charmers to change this (no one's asked for that, and 5s has worked well). I'm on board with explaining in the `pebble.Client` docstring what it means though!
IronCore864: I have added a little explanation in `pebble.Client` docstring. Please take another look.
IronCore864: > Looks good to me. Let's just remove the 3 extraneous files added under `docs` (do we need to add something more to `.gitignore`?)

Sorry, it was a bad merge; the history is too complicated so I rebased everything to fix it.

Patch:
diff --git a/CHANGES.md b/CHANGES.md
index 07ae6bb..cea76b8 100644
--- a/CHANGES.md
+++ b/CHANGES.md
@@ -2,6 +2,7 @@
 
 * Updated Pebble Notices `get_notices` parameter name to `users=all` (previously `select=all`).
 * Added `Model.get_cloud_spec` which uses the `credential-get` hook tool to get details of the cloud where the model is deployed.
+* Fixed an issue where `pebble.Client.exec` might leak a `socket.timeout` (`builtins.TimeoutError`) exception.
 * Updated code examples in the docstring of `ops.testing` from unittest to pytest style.
 * Refactored main.py, creating a new `_Manager` class.
 
diff --git a/ops/pebble.py b/ops/pebble.py
index 60bb9d7..638885f 100644
--- a/ops/pebble.py
+++ b/ops/pebble.py
@@ -18,6 +18,7 @@ For a command-line interface for local testing, see test/pebble_cli.py.
 """
 
 import binascii
+import builtins
 import copy
 import dataclasses
 import datetime
@@ -1722,6 +1723,11 @@ class Client:
     connecting to or transferring data with Pebble will raise a :class:`ConnectionError`. When an
     error occurs executing the request, such as trying to add an invalid layer or execute a command
     that does not exist, an :class:`APIError` is raised.
+
+    The ``timeout`` parameter specifies a timeout in seconds for blocking operations like the
+    connection attempt to Pebble; used by ``urllib.request.OpenerDirector.open``. It's not for
+    methods like :meth:`start_services` and :meth:`replan_services` mentioned above, and it's not
+    for the command execution timeout defined in method :meth:`Client.exec`.
     """
 
     _chunk_size = 8192
@@ -2029,8 +2035,10 @@ class Client:
 
             try:
                 return self._wait_change(change_id, this_timeout)
-            except TimeoutError:
-                # Catch timeout from wait endpoint and loop to check deadline
+            except (socket.timeout, builtins.TimeoutError):
+                # NOTE: in Python 3.10 socket.timeout is an alias of TimeoutError,
+                # but we still need to support Python 3.8, so catch both.
+                # Catch timeout from wait endpoint and loop to check deadline.
                 pass
 
         raise TimeoutError(f'timed out waiting for change {change_id} ({timeout} seconds)')


Test patch:
diff --git a/test/test_pebble.py b/test/test_pebble.py
index ccd96d0..5be2266 100644
--- a/test/test_pebble.py
+++ b/test/test_pebble.py
@@ -18,6 +18,7 @@ import email.parser
 import io
 import json
 import signal
+import socket
 import tempfile
 import test.fake_pebble as fake_pebble
 import typing
@@ -2028,6 +2029,18 @@ class TestClient(unittest.TestCase):
             ('GET', '/v1/changes/70/wait', {'timeout': '4.000s'}, None),
         ])
 
+    def test_wait_change_socket_timeout(self):
+        def timeout_response(n: float):
+            self.time.sleep(n)
+            raise socket.timeout("socket.timeout: timed out")
+
+        self.client.responses.append(lambda: timeout_response(3))
+
+        with self.assertRaises(pebble.TimeoutError) as cm:
+            self.client.wait_change(pebble.ChangeID('70'), timeout=3)
+        self.assertIsInstance(cm.exception, pebble.Error)
+        self.assertIsInstance(cm.exception, TimeoutError)
+
     def test_add_layer(self):
         okay_response = {
             "result": True,