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.

Sign up for GitHub

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

Jump to bottom

Timeout Exception on Bus Reply. #244

Closed
Piero512 opened this issue May 30, 2021 · 8 comments
Closed

Timeout Exception on Bus Reply. #244

Piero512 opened this issue May 30, 2021 · 8 comments

Comments

@Piero512
Copy link

Piero512 commented May 30, 2021 •
edited

Hi

I've been recently bitten by an update in DBus, as now it seems that syncronous DBus calls receive a Timeout from the server, in about 5 seconds.

The problem happens on Ubuntu 20.04 LTS, with a default install of flutter and dbus 0.5.x. This issue did not happen on dbus 0.3.x

I receive the following unexpected exception from the server:

org.freedesktop.Avahi.TimeoutError: TimeoutReached

As I traced back into my code, this happens when calling the method org.freedesktop.Avahi.Server.ResolveService using the avahi service files.
The stack trace is the following:

00:15 +0: external_api Able to create a discovery without D-Bus complaining    
Enabling workaround for V1 API with the 100ms wait behavior. Update your Avahi version to 0.8 or later if you want this warning to disappear.
00:17 +3: end-to-end Broadcast name and receive them on service enumeration    
Enabling workaround for V1 API with the 100ms wait behavior. Update your Avahi version to 0.8 or later if you want this warning to disappear.
Cached service received: AvahiServiceBrowserItemNew(path: 'DBusObjectPath('/Client57/ServiceBrowser1')',interface: '2',protocol: 'AvahiProtocol.AVAHI_PROTO_INET6', name: 'ItemNew',type: '_bonsoire2e._tcp',domain: 'local'
DBG: AvahiServiceBrowserItemNew(path: 'DBusObjectPath('/Client57/ServiceBrowser1')',interface: '2',protocol: 'AvahiProtocol.AVAHI_PROTO_INET6', name: 'ItemNew',type: '_bonsoire2e._tcp',domain: 'local'
Item added! AvahiServiceBrowserItemNew(path: 'DBusObjectPath('/Client57/ServiceBrowser1')',interface: '2',protocol: 'AvahiProtocol.AVAHI_PROTO_INET6', name: 'ItemNew',type: '_bonsoire2e._tcp',domain: 'local'
DBG: AvahiServiceBrowserItemNew(path: 'DBusObjectPath('/Client57/ServiceBrowser1')',interface: '2',protocol: 'AvahiProtocol.AVAHI_PROTO_INET6', name: 'ItemNew',type: '_bonsoire2e._tcp',domain: 'local'
Cached service received: AvahiServiceBrowserItemNew(path: 'DBusObjectPath('/Client57/ServiceBrowser1')',interface: '2',protocol: 'AvahiProtocol.AVAHI_PROTO_INET', name: 'ItemNew',type: '_bonsoire2e._tcp',domain: 'local'
DBG: AvahiServiceBrowserItemNew(path: 'DBusObjectPath('/Client57/ServiceBrowser1')',interface: '2',protocol: 'AvahiProtocol.AVAHI_PROTO_INET', name: 'ItemNew',type: '_bonsoire2e._tcp',domain: 'local'
Item added! AvahiServiceBrowserItemNew(path: 'DBusObjectPath('/Client57/ServiceBrowser1')',interface: '2',protocol: 'AvahiProtocol.AVAHI_PROTO_INET', name: 'ItemNew',type: '_bonsoire2e._tcp',domain: 'local'
DBG: AvahiServiceBrowserItemNew(path: 'DBusObjectPath('/Client57/ServiceBrowser1')',interface: '2',protocol: 'AvahiProtocol.AVAHI_PROTO_INET', name: 'ItemNew',type: '_bonsoire2e._tcp',domain: 'local'
Cached service received: AvahiServiceBrowserItemNew(path: 'DBusObjectPath('/Client57/ServiceBrowser1')',interface: '1',protocol: 'AvahiProtocol.AVAHI_PROTO_INET', name: 'ItemNew',type: '_bonsoire2e._tcp',domain: 'local'
DBG: AvahiServiceBrowserItemNew(path: 'DBusObjectPath('/Client57/ServiceBrowser1')',interface: '1',protocol: 'AvahiProtocol.AVAHI_PROTO_INET', name: 'ItemNew',type: '_bonsoire2e._tcp',domain: 'local'
Item added! AvahiServiceBrowserItemNew(path: 'DBusObjectPath('/Client57/ServiceBrowser1')',interface: '1',protocol: 'AvahiProtocol.AVAHI_PROTO_INET', name: 'ItemNew',type: '_bonsoire2e._tcp',domain: 'local'
DBG: AvahiServiceBrowserItemNew(path: 'DBusObjectPath('/Client57/ServiceBrowser1')',interface: '1',protocol: 'AvahiProtocol.AVAHI_PROTO_INET', name: 'ItemNew',type: '_bonsoire2e._tcp',domain: 'local'
00:22 +3 -1: end-to-end Broadcast name and receive them on service enumeration [E]
  org.freedesktop.Avahi.TimeoutError: Timeout reached
  package:dbus/src/dbus_client.dart 1067:7                                DBusClient._callMethod
  ===== asynchronous gap ===========================
  dart:async                                                              _asyncErrorWrapperHelper
  package:bonsoir_linux_dbus/src/linux_dbus_bonsoir_discovery.dart 49:13  LinuxDBusBonsoirDiscovery.ready.<fn>
  ===== asynchronous gap ===========================
  dart:async                                                              _StreamImpl.listen
  package:dbus/src/dbus_client.dart 126:31                                DBusSignalStream.listen
  package:bonsoir_linux_dbus/src/linux_dbus_bonsoir_discovery.dart 39:12  LinuxDBusBonsoirDiscovery.ready
  ===== asynchronous gap ===========================
  dart:async                                                              _asyncThenWrapperHelper
  test/bonsoir_linux_dbus_test.dart 70:48                                 main.<fn>.<fn>
  test/bonsoir_linux_dbus_test.dart 61:68                                 main.<fn>.<fn>
  
  org.freedesktop.Avahi.TimeoutError: Timeout reached
  package:dbus/src/dbus_client.dart 1067:7                                DBusClient._callMethod
  ===== asynchronous gap ===========================
  dart:async                                                              _asyncErrorWrapperHelper
  package:bonsoir_linux_dbus/src/linux_dbus_bonsoir_discovery.dart 84:7   LinuxDBusBonsoirDiscovery.start.<fn>
  package:bonsoir_linux_dbus/src/linux_dbus_bonsoir_discovery.dart 76:57  LinuxDBusBonsoirDiscovery.start.<fn>
  ===== asynchronous gap ===========================
  dart:async                                                              _ForwardingStream.listen
  package:bonsoir_linux_dbus/src/linux_dbus_bonsoir_discovery.dart 76:50  LinuxDBusBonsoirDiscovery.start
  test/bonsoir_linux_dbus_test.dart 121:50                                main.<fn>.<fn>
  ===== asynchronous gap ===========================
  dart:async                                                              _asyncThenWrapperHelper
  test/bonsoir_linux_dbus_test.dart                                       main.<fn>.<fn>
  
  org.freedesktop.Avahi.TimeoutError: Timeout reached
  package:dbus/src/dbus_client.dart 1067:7                                DBusClient._callMethod
  ===== asynchronous gap ===========================
  dart:async                                                              _asyncErrorWrapperHelper
  package:bonsoir_linux_dbus/src/linux_dbus_bonsoir_discovery.dart 49:13  LinuxDBusBonsoirDiscovery.ready.<fn>
  ===== asynchronous gap ===========================
  dart:async                                                              _StreamImpl.listen
  package:dbus/src/dbus_client.dart 126:31                                DBusSignalStream.listen
  package:bonsoir_linux_dbus/src/linux_dbus_bonsoir_discovery.dart 39:12  LinuxDBusBonsoirDiscovery.ready
  ===== asynchronous gap ===========================
  dart:async                                                              _asyncThenWrapperHelper
  test/bonsoir_linux_dbus_test.dart 70:48                                 main.<fn>.<fn>
  test/bonsoir_linux_dbus_test.dart 61:68                                 main.<fn>.<fn>
  
  org.freedesktop.Avahi.TimeoutError: Timeout reached
  package:dbus/src/dbus_client.dart 1067:7                                DBusClient._callMethod
  ===== asynchronous gap ===========================
  dart:async                                                              _asyncErrorWrapperHelper
  package:bonsoir_linux_dbus/src/linux_dbus_bonsoir_discovery.dart 84:7   LinuxDBusBonsoirDiscovery.start.<fn>
  package:bonsoir_linux_dbus/src/linux_dbus_bonsoir_discovery.dart 76:57  LinuxDBusBonsoirDiscovery.start.<fn>
  ===== asynchronous gap ===========================
  dart:async                                                              _ForwardingStream.listen
  package:bonsoir_linux_dbus/src/linux_dbus_bonsoir_discovery.dart 76:50  LinuxDBusBonsoirDiscovery.start
  test/bonsoir_linux_dbus_test.dart 121:50                                main.<fn>.<fn>
  ===== asynchronous gap ===========================
  dart:async                                                              _asyncThenWrapperHelper
  test/bonsoir_linux_dbus_test.dart                                       main.<fn>.<fn>
  
  org.freedesktop.Avahi.TimeoutError: Timeout reached
  package:dbus/src/dbus_client.dart 1067:7                                DBusClient._callMethod
  ===== asynchronous gap ===========================
  dart:async                                                              _asyncErrorWrapperHelper
  package:bonsoir_linux_dbus/src/linux_dbus_bonsoir_discovery.dart 49:13  LinuxDBusBonsoirDiscovery.ready.<fn>
  ===== asynchronous gap ===========================
  dart:async                                                              _StreamImpl.listen
  package:dbus/src/dbus_client.dart 126:31                                DBusSignalStream.listen
  package:bonsoir_linux_dbus/src/linux_dbus_bonsoir_discovery.dart 39:12  LinuxDBusBonsoirDiscovery.ready
  ===== asynchronous gap ===========================
  dart:async                                                              _asyncThenWrapperHelper
  test/bonsoir_linux_dbus_test.dart 70:48                                 main.<fn>.<fn>
  test/bonsoir_linux_dbus_test.dart 61:68                                 main.<fn>.<fn>
  
  org.freedesktop.Avahi.TimeoutError: Timeout reached
  package:dbus/src/dbus_client.dart 1067:7                                DBusClient._callMethod
  ===== asynchronous gap ===========================
  dart:async                                                              _asyncErrorWrapperHelper
  package:bonsoir_linux_dbus/src/linux_dbus_bonsoir_discovery.dart 84:7   LinuxDBusBonsoirDiscovery.start.<fn>
  package:bonsoir_linux_dbus/src/linux_dbus_bonsoir_discovery.dart 76:57  LinuxDBusBonsoirDiscovery.start.<fn>
  ===== asynchronous gap ===========================
  dart:async                                                              _ForwardingStream.listen
  package:bonsoir_linux_dbus/src/linux_dbus_bonsoir_discovery.dart 76:50  LinuxDBusBonsoirDiscovery.start
  test/bonsoir_linux_dbus_test.dart 121:50                                main.<fn>.<fn>
  ===== asynchronous gap ===========================
  dart:async                                                              _asyncThenWrapperHelper
  test/bonsoir_linux_dbus_test.dart                                       main.<fn>.<fn>
  
00:23 +3 -1: Some tests failed.

My test file and entire source code is public at https://github.com/Piero512/bonsoir_linux_dbus

It seems like DBus is missing a timeout parameter for the method call and now that it parses the error messages correctly, this happens.
@robert-ancell
Copy link
Collaborator

This is a weird one:

  • The org.freedesktop.Avahi.TimeoutError is being sent by the Avahi daemon - so the timeout is occurring outside of dbus.dart.
  • There is no D-Bus timeout parameter in the protocol. So there's been no change here between dbus 0.3 and 0.5. If you wanted a client side timeout, you would have to implement that yourself.
  • Looking at your code, the method calls should be the same between 0.3 and 0.5.

Can you double check if rolling back to 0.3 fixes the issues?

@Piero512
Copy link
Author

Ok. I've reverted my changes in a separate branch, and the test runs with the expected results. Maybe there's a way I can isolate two packages that replicate the issue?

@robert-ancell
Copy link
Collaborator

Can you make a small project that reproduces the issue and does nothing else?

@robert-ancell robert-ancell reopened this Jun 1, 2021
@Piero512
Copy link
Author

Piero512 commented Jun 2, 2021

I'll try my best this weekend.

@Piero512
Copy link
Author

Piero512 commented Jun 7, 2021

I finally got around to it. I reduced the code to review by a lot in this repo. https://github.com/Piero512/broken_dbus

@robert-ancell
Copy link
Collaborator

Thanks @Piero512. I can confirm running that here gives org.freedesktop.Avahi.TimeoutError: Timeout reached

@robert-ancell
Copy link
Collaborator

I've tried https://github.com/Piero512/broken_dbus by using dbus 0.3.3 by changing the following in the pubspec.yaml and modifying the code to work with the older dbus API:

dependencies: 
  dbus: ^0.3.3

I can confirm that exactly the same behaviour works in 0.3.3 (i.e. the timeout error is received), so this is not a bug in dbus.dart, and is indeed coming from the Avahi daemon.

It may be have been your were ignoring the error in older code, which now generates an exception in dbus.dart 0.5. If that is the case, you should update your code to something like:

DBusMethodSuccessResponse result;
try {
  result = await server.callResolveService(...);
} on DBusMethodResponseException catch (e) {
  if (e.response.errorName == 'org.freedesktop.Avahi.TimeoutError') {
    // Handle this error
  } else {
    rethrow;
  }
}

@Piero512
Copy link
Author

Piero512 commented Jun 10, 2021 •
edited

Thanks for the help diagnosing this issue. I think I might migrate to ServiceResolver since ignoring the exception doesn't work, neither does retrying, and it's weird that it also happened on dbus 0.3.3 but the services resolved nonetheless.

Update: Moving to Service Resolver didn't solve the issue in dbus 0.5.1 😭

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@robert-ancell @Piero512