Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix: handling of None messages from notify callback #236

Merged
merged 12 commits into from
Sep 7, 2023

Conversation

Mocramis
Copy link
Contributor

@Mocramis Mocramis commented Sep 1, 2023

This is especially common as BaseMessageBus._finalize calls handler(None, err) when an exception is raised.

From the surrounding code, it seems the common assumption is that msg should be None if err is set. However you might want to print msg if it is here even if there is an err, but then the logs would be awkward no ?

Did not take the time to build a test to reproduce the issue though

@codecov
Copy link

codecov bot commented Sep 1, 2023

Codecov Report

Patch coverage has no change and project coverage change: -0.19% ⚠️

Comparison is base (6f6f5f8) 82.84% compared to head (1da13ff) 82.66%.
Report is 1 commits behind head on main.

Additional details and impacted files
@@            Coverage Diff             @@
##             main     #236      +/-   ##
==========================================
- Coverage   82.84%   82.66%   -0.19%     
==========================================
  Files          28       28              
  Lines        3259     3259              
  Branches      674      674              
==========================================
- Hits         2700     2694       -6     
- Misses        342      346       +4     
- Partials      217      219       +2     
Files Changed Coverage Δ
src/dbus_fast/__version__.py 0.00% <0.00%> (ø)
src/dbus_fast/message_bus.py 71.63% <0.00%> (ø)

... and 2 files with indirect coverage changes

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

@bdraco
Copy link
Member

bdraco commented Sep 1, 2023

Looks ok, but we do need a test before merging

@Mocramis
Copy link
Contributor Author

Mocramis commented Sep 4, 2023

Hello, so i have a reproducer but i cannot automate it because this is triggered through a race condition and the side-effect is a log:

import pytest

from dbus_fast import DBusError, aio, glib
from dbus_fast.service import ServiceInterface


class ExampleInterface(ServiceInterface):
    def __init__(self):
        super().__init__("test.interface")


@pytest.mark.asyncio
async def test_fast_disconnect():
    bus_name = "aio.client.test.methods"

    bus = await aio.MessageBus().connect()
    bus2 = await aio.MessageBus().connect()
    await bus.request_name(bus_name)
    service_interface = ExampleInterface()
    bus.export("/test/path", service_interface)
    introspection = await bus2.introspect(bus_name, "/test/path")
    bus2.get_proxy_object(bus_name, "/test/path", introspection)
    bus2.disconnect()
    raise Exception("Failed")

This reproduce the error if you look at the captured stderr:

------------------------------------------------------------------------------------------------- Captured log call -------------------------------------------------------------------------------------------------
ERROR    root:message_bus.py:1194 add match request failed. match="sender='org.freedesktop.DBus',interface='org.freedesktop.DBus',path='/org/freedesktop/DBus',member='NameOwnerChanged'",
WARNING  root:message_bus.py:584 a message handler threw an exception on shutdown
Traceback (most recent call last):
  File "/home/mocramis/misc/dbus-fast/src/dbus_fast/aio/message_reader.py", line 22, in _message_reader
    message = unmarshaller._unmarshall()
  File "/home/mocramis/misc/dbus-fast/src/dbus_fast/_private/unmarshaller.py", line 742, in _unmarshall
    self._read_header()
  File "/home/mocramis/misc/dbus-fast/src/dbus_fast/_private/unmarshaller.py", line 611, in _read_header
    self._read_to_pos(HEADER_SIGNATURE_SIZE)
  File "/home/mocramis/misc/dbus-fast/src/dbus_fast/_private/unmarshaller.py", line 366, in _read_to_pos
    self._read_sock_without_fds(pos)
  File "/home/mocramis/misc/dbus-fast/src/dbus_fast/_private/unmarshaller.py", line 329, in _read_sock_without_fds
    raise EOFError()
EOFError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/mocramis/misc/dbus-fast/src/dbus_fast/message_bus.py", line 582, in _finalize
    handler(None, err)
  File "/home/mocramis/misc/dbus-fast/src/dbus_fast/message_bus.py", line 737, in _reply_notify
    callback(reply, err)
  File "/home/mocramis/misc/dbus-fast/src/dbus_fast/message_bus.py", line 1197, in add_match_notify
    if msg.message_type == MessageType.ERROR:
AttributeError: 'NoneType' object has no attribute 'message_type'

However if i try to use caplog to capture the logs, the error suddenly disapear.

Any thoughs about this ?

thanks.

@bdraco
Copy link
Member

bdraco commented Sep 4, 2023

Even if the test doesn't fail before it's still useful in case we break something else in the future as this project is definitely lighter on coverage than I would like

@Mocramis Mocramis force-pushed the notify_callback_empty_message branch 2 times, most recently from bd38eb5 to 363b7a1 Compare September 4, 2023 14:45
The test does not fails but outputs the following erroneous logs:

  ERROR    root:message_bus.py:1194 add match request failed. match="sender='org.freedesktop.DBus',interface='org.freedesktop.DBus',path='/org/freedesktop/DBus',member='NameOwnerChanged'",
  WARNING  root:message_bus.py:584 a message handler threw an exception on shutdown
  Traceback (most recent call last):
    File "/home/mocramis/misc/dbus-fast/src/dbus_fast/aio/message_reader.py", line 22, in _message_reader
      message = unmarshaller._unmarshall()
    File "/home/mocramis/misc/dbus-fast/src/dbus_fast/_private/unmarshaller.py", line 742, in _unmarshall
      self._read_header()
    File "/home/mocramis/misc/dbus-fast/src/dbus_fast/_private/unmarshaller.py", line 611, in _read_header
      self._read_to_pos(HEADER_SIGNATURE_SIZE)
    File "/home/mocramis/misc/dbus-fast/src/dbus_fast/_private/unmarshaller.py", line 366, in _read_to_pos
      self._read_sock_without_fds(pos)
    File "/home/mocramis/misc/dbus-fast/src/dbus_fast/_private/unmarshaller.py", line 329, in _read_sock_without_fds
      raise EOFError()
  EOFError

  During handling of the above exception, another exception occurred:

  Traceback (most recent call last):
    File "/home/mocramis/misc/dbus-fast/src/dbus_fast/message_bus.py", line 582, in _finalize
      handler(None, err)
    File "/home/mocramis/misc/dbus-fast/src/dbus_fast/message_bus.py", line 737, in _reply_notify
      callback(reply, err)
    File "/home/mocramis/misc/dbus-fast/src/dbus_fast/message_bus.py", line 1197, in add_match_notify
      if msg.message_type == MessageType.ERROR:
  AttributeError: 'NoneType' object has no attribute 'message_type'

However, trying to capture those logs seems to prevent the race
condition from happening. Therefore, we just run the test for coverage.
@Mocramis Mocramis force-pushed the notify_callback_empty_message branch from 363b7a1 to 550db23 Compare September 4, 2023 14:50
@Mocramis
Copy link
Contributor Author

Mocramis commented Sep 4, 2023

Should i increase the pytest timeout apparently adding this one test makes us get over the 5s limit on py38 and py39 (and the other are not very far from it)
would 10 second be ok ?

Remy Noel added 2 commits September 4, 2023 17:21
previous added test pushed the testsuite above 5s on py38 ant py39/
This is especially common as BaseMessageBus._finalize calls handler(None, err)
when an exception is raised.
@Mocramis Mocramis force-pushed the notify_callback_empty_message branch from 550db23 to 3b4813a Compare September 4, 2023 15:22
@Mocramis
Copy link
Contributor Author

Mocramis commented Sep 4, 2023

The timeout is not the issue, i fail to understand how i broke 3.8 and 3.9, i do not reproduce the issue locally with my 3.9 python version :/

Copy link
Member

@bdraco bdraco left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks @Mocramis

@bdraco
Copy link
Member

bdraco commented Sep 7, 2023

@bdraco bdraco merged commit 14f52f2 into Bluetooth-Devices:main Sep 7, 2023
17 of 19 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants