Fix bridge crashes on early channel opening failure

[martinpitt]

These have plagued c-files for a while, see e.g. this crash (top of the weather report).

The second patch is fixing the crash that I got when I was smoke-testing the first one. See cockpit-project/bots#6730 (comment) . It's also on the weather report, example

I've tried for 90 mins to write an unit test for the first one, but I just don't grasp that. I monkeyed around with

diff --git src/cockpit/transports.py src/cockpit/transports.py
index 8aabc7d83..491638587 100644
--- src/cockpit/transports.py
+++ src/cockpit/transports.py
@@ -241,9 +241,11 @@ class _Transport(asyncio.Transport):
 
         try:
             n_bytes = os.write(self._out_fd, data)
+            logger.warning('Transport.write %r succeeded %i', data, n_bytes)
         except BlockingIOError:
             n_bytes = 0
         except OSError as exc:
+            logger.warning('Transport.write %r failed %r', data, exc)
             self.abort(exc)
             return
 
diff --git test/pytest/mocktransport.py test/pytest/mocktransport.py
index ed2c6f721..b06e6b4b9 100644
--- test/pytest/mocktransport.py
+++ test/pytest/mocktransport.py
@@ -25,7 +25,9 @@ class MockTransport(asyncio.Transport):
     def send_data(self, channel: str, data: bytes) -> None:
         msg = channel.encode('ascii') + b'\n' + data
         msg = str(len(msg)).encode('ascii') + b'\n' + msg
+        print("XXXXX MockTransport send_data %r" % data)
         self.protocol.data_received(msg)
+        print("XXXXX MockTransport send_data done")
 
     def send_init(self, version=1, host=MOCK_HOSTNAME, **kwargs):
         self.send_json('', command='init', version=version, host=host, **kwargs)
@@ -124,7 +126,9 @@ class MockTransport(asyncio.Transport):
 
     async def assert_msg(self, expected_channel: str, absent_keys: 'Iterable[str]' = (),
                          **kwargs: JsonValue) -> JsonObject:
+        print("XXX assert_msg waiting next_msg on", expected_channel)
         msg = await self.next_msg(expected_channel)
+        print("XXX assert_msg got next_msg", msg)
         assert msg == dict(msg, **{k.replace('_', '-'): v for k, v in kwargs.items()}), msg
         for absent_key in absent_keys:
             assert absent_key not in msg
diff --git test/pytest/test_bridge.py test/pytest/test_bridge.py
index b4b02d78c..a4ae51bd2 100644
--- test/pytest/test_bridge.py
+++ test/pytest/test_bridge.py
@@ -1379,3 +1379,16 @@ async def test_fsinfo_targets(transport: MockTransport, tmp_path: Path) -> None:
     # double-check with the non-watch variant
     client = await FsInfoClient.open(transport, tmp_path, ['type', 'target', 'targets'], fnmatch='l*')
     assert await client.wait() == state
+
+
+@pytest.mark.asyncio
+async def test_early_write_error(transport: MockTransport, monkeypatch: pytest.MonkeyPatch) -> None:
+    def fail_write(_data):
+        # transport.close_future.set_result(OSError("moo"))
+        transport.protocol.connection_lost(OSError("meh"))
+        transport.send_close("1.1", problem="kaputt")
+
+    # MockTransport.write = fail_write
+    # monkeypatch.setattr(transport, 'write', unittest.mock.Mock(side_effect=OSError))
+    monkeypatch.setattr(transport, 'write', fail_write)
+    await transport.check_open('echo', channel="1.1", problem="mieps")
diff --git test/pytest/test_transport.py test/pytest/test_transport.py
index 7c819c009..cedaf62a0 100644
--- test/pytest/test_transport.py
+++ test/pytest/test_transport.py
@@ -469,3 +469,13 @@ class TestSubprocessTransport:
         while protocol.transport is not None:
             await asyncio.sleep(0.1)
         assert protocol.transport is None
+
+    @pytest.mark.asyncio
+    async def test_early_write_error(self, monkeypatch: pytest.MonkeyPatch) -> None:
+        loop = asyncio.get_running_loop()
+        protocol = Protocol()
+        monkeypatch.setattr(os, 'write', unittest.mock.Mock(side_effect=OSError))
+        transport = cockpit.transports.SubprocessTransport(loop, protocol, ['true'])
+        protocol.close_on_eof = False
+        while not protocol.exited:
+            await asyncio.sleep(0.1)

But nothing here really fits -- test_transport all uses MockTransport which is so different in behaviour from the real _Transport class that I find it (too) hard to reproduce the behaviour. The test_bridge level felt more promising, but I couldn't make that work either.

[martinpitt]

Hmm, our bridge surely is rather crash happy 🤔 (unrelated, retrying)

[allisonkarlitskaya]

This is the wrong spot for that. Please move this to an initialization at the class level where all the other variables are initialized. I'm not sure why I missed this one...

[martinpitt]

You know I despise instance variables that pretend to be class variables. That be the wrong spot IMO. If you insist I'll do it to get it out of the way, but this really belongs into the constructor (and open() is kinda sorta the constructor for Channels).

[allisonkarlitskaya]

This conditional sort of invalidates the point of the comment above.

There's a thorny philosophical issue behind all of this: what's supposed to happen when writing to the transport fails with an OSError. That's supposed to result in the transport being closed with that exception, of course, but should it also bubble up into the code?

If so, I feel like we should do more to guard individual callers against having to deal with this. I don't want to have very channel having to think about what might happen if their .send() calls throw...

[allisonkarlitskaya]

Which is to say: let me do a bit of research on this and see what the standard transports do.

[allisonkarlitskaya]

import asyncio
import sys
from typing import override


class Prot(asyncio.Protocol):
    @override
    def connection_made(self, transport: asyncio.BaseTransport) -> None:
        assert isinstance(transport, asyncio.WriteTransport)
        transport.write(b'hihi')
        print('I survived')

    @override
    def connection_lost(self, exc: Exception | None) -> None:
        print('lost', exc)

async def run() -> None:
    loop = asyncio.get_running_loop()
    await loop.connect_write_pipe(Prot, sys.stdin)
    await asyncio.sleep(1000)


asyncio.run(run())

yields

$ python3 x.py < /dev/null
I survived
lost [Errno 9] Bad file descriptor

which is to say: the transport protects the caller of .write() from the exception.

[allisonkarlitskaya]

Our transports should guard callers in the same way:

        try:
            n_bytes = os.write(self._out_fd, data)
        except BlockingIOError:
            n_bytes = 0
        except OSError as exc:
            self.abort(exc)
            return

There's a critical difference, though: we call .abort() directly, which immediately calls .connection_lost() on the Protocol.

    def abort(self, exc: 'Exception | None' = None) -> None:
        self._closing = True
        self._close_reader()
        self._remove_write_queue()
        self._protocol.connection_lost(exc)
        self._close()

The standard transports punt it to the next mainloop iteration.

    def _close(self, exc=None):
        self._closing = True
        if self._buffer:
            self._loop._remove_writer(self._fileno)
        self._buffer.clear()
        self._loop._remove_reader(self._fileno)
        self._loop.call_soon(self._call_connection_lost, exc)

So with a standard transport, the caller's code runs first, but with ours, the abort code runs first.

The correct solution here is to change our transport to be more like the stdlib ones. This might have also been the root cause of #20634 and other similar bugs: it's not that we close multiple times — it's that we never finished opening.

[allisonkarlitskaya]

as an aside: I remember when I was writing this transport code way at the beginning I was in a hurry and I thought "meh, I don't understand why the standard transports do it this way — it seems pointless and unnecessary. I'll do it my way and we can change it if we find out that it's wrong."

😅

[allisonkarlitskaya]

At least part of this is handled in #20881 now.

[allisonkarlitskaya]

At least part of this is handled in #20881 now.

and now the second part of it is handled there too. Let's close this one.