`split-gpg2`: `NotImplementedError` in logs

Euwiiwueir commented 2 months ago

Qubes OS release

4.2 Debian 12 templates

Brief summary

In attempting to set up split-gpg2 I noticed this pattern logged in journalctl:

servervm qubes.Gpg2+-clientvm[1120]: Traceback (most recent call last):
servervm qubes.Gpg2+-clientvm[1120]:   File "<frozen runpy>", line 198, in _run_module_as_main
servervm qubes.Gpg2+-clientvm[1120]:   File "<frozen runpy>", line 88, in _run_code
servervm qubes.Gpg2+-clientvm[1120]:   File "/usr/lib/python3/dist-packages/splitgpg2/__main__.py", line 3, in <module>
servervm qubes.Gpg2+-clientvm[1120]:     main()
servervm qubes.Gpg2+-clientvm[1120]:   File "/usr/lib/python3/dist-packages/splitgpg2/__init__.py", line 1457, in main
servervm qubes.Gpg2+-clientvm[1120]:     loop.run_until_complete(server.run())
servervm qubes.Gpg2+-clientvm[1120]:   File "/usr/lib/python3.11/asyncio/base_events.py", line 653, in run_until_complete
servervm qubes.Gpg2+-clientvm[1120]:     return future.result()
servervm qubes.Gpg2+-clientvm[1120]:            ^^^^^^^^^^^^^^^
servervm qubes.Gpg2+-clientvm[1120]:   File "/usr/lib/python3/dist-packages/splitgpg2/__init__.py", line 426, in run
servervm qubes.Gpg2+-clientvm[1120]:     await self.client_writer.wait_closed()
servervm qubes.Gpg2+-clientvm[1120]:   File "/usr/lib/python3.11/asyncio/streams.py", line 350, in wait_closed
servervm qubes.Gpg2+-clientvm[1120]:     await self._protocol._get_close_waiter(self)
servervm qubes.Gpg2+-clientvm[1120]:           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
servervm qubes.Gpg2+-clientvm[1120]:   File "/usr/lib/python3.11/asyncio/streams.py", line 178, in _get_close_waiter
servervm qubes.Gpg2+-clientvm[1120]:     raise NotImplementedError
servervm qubes.Gpg2+-clientvm[1120]: NotImplementedError

(The logging above comes from the server VM journal but it's also logged in the client VM under the split-gpg2-client.service unit.)

Having stepped through the code, I think it's probably innocuous, as it occurs during cleanup. But it is alarming logging coming from security-related software so it should probably be fixed.

The cause seems to be:

asyncio.streams.FlowControlMixin protocol instantiated here
Later, the writer owning the protocol is instructed to close here
This initiates a call on the protocol to an internal _get_close_waiter() function which is "implemented" on asyncio.streams.FlowControlMixin like so:
```
def _get_close_waiter(self, stream):
raise NotImplementedError
```

At least, this is my best understanding. I posted about this on the forum but got no other reports, therefore I'm not super confident it shows up for other users.

Steps to reproduce

Install and set up split-gpg2 on a server and client, attempt to sign something on the client, then check the logs.

Expected behavior

No logging

Actual behavior

Scary logging

Euwiiwueir commented 2 months ago

Recent posts in the forum thread have me wondering if this is something specific to my configuration rather than a more general issue. I will take another look when I can and follow up here.

DemiMarie commented 4 weeks ago

This is not specific to your configuration. It is a consequence of split-gpg2 erroneously instantiating asyncio.StreamWriter by calling its constructor, which isn’t allowed, and using asyncio.FlowControlMixin, which isn’t part of the public Python API.

There are two correct ways to fix this:

Stop using StreamReader and StreamWriter, possibly by including a copy of the classes in split-gpg2.
Create the objects by using open_unix_connection or create_unix_server.

@marmarek which do you prefer?

QubesOS / qubes-issues