Bug #2233
closedofono: Sometimes an interface is announced before being present on the bus
0%
Description
We sometimes seem to be receiving a signal from ofono for a modem stating that an interface is available. When we detect it's available, we try to use it right away to configure some stuff. Sometimes, however, it seems the interface is not yet there and the method calls fails:
10:28:00 bus /sierra_1: Powering on [trial-19↪sms:sysmo↪mo_mt_sms.py:20↪/sierra_1] [ofono_client.py:217] 10:28:00 bus /sierra_1: Setting Powered True [trial-19↪sms:sysmo↪mo_mt_sms.py:20↪/sierra_1] [ofono_client.py:92] 10:28:03 bus /sierra_1: Setting Online True [trial-19↪sms:sysmo↪mo_mt_sms.py:20↪/sierra_1] [ofono_client.py:92] 10:28:04 bus /sierra_2: Powering on [trial-19↪sms:sysmo↪mo_mt_sms.py:21↪/sierra_2] [ofono_client.py:217] 10:28:04 bus /sierra_2: Setting Powered True [trial-19↪sms:sysmo↪mo_mt_sms.py:21↪/sierra_2] [ofono_client.py:92] 10:28:04 bus /sierra_2: Setting Online True [trial-19↪sms:sysmo↪mo_mt_sms.py:21↪/sierra_2] [ofono_client.py:92] 10:28:05 bus /sierra_1: ERR: KeyError: 'org.ofono.NetworkRegistration' [log.py:317] 10:28:08 bus /sierra_1: ERR: Interface enabled by signal, but not available: org.ofono.MessageManager [trial-19↪sms:sysmo↪mo_ mt_sms.py:21↪modem.enable(org.ofono.MessageManager)↪/sierra_1] [ofono_client.py:154] 10:28:08 bus /sierra_1: ERR: KeyError: 'org.ofono.MessageManager' [log.py:317] 10:28:09 bus /sierra_2: ERR: KeyError: 'org.ofono.NetworkRegistration' [log.py:317] 10:28:12 bus /sierra_2: ERR: Interface enabled by signal, but not available: org.ofono.MessageManager [trial-19↪sms:sysmo↪mo_ mt_sms.py:21↪modem.enable(org.ofono.MessageManager)↪/sierra_2] [ofono_client.py:154] 10:28:12 bus /sierra_2: ERR: KeyError: 'org.ofono.MessageManager' [log.py:317] 10:28:13 bus /sierra_1: connect to 901 70 [trial-19↪sms:sysmo↪mo_mt_sms.py:23↪/sierra_1] [ofono_client.py:227] 10:28:13 tst mo_mt_sms.py:23: FAIL [trial-19↪sms:sysmo↪mo_mt_sms.py:23] [suite.py:108] 10:28:13 tst mo_mt_sms.py:23: ERR: KeyError: 'org.ofono.NetworkRegistration' [sms:sysmo↪mo_mt_sms.py:23] [proxy.py:102: raise KeyE rror(iface)] 10:28:13 run osmo-nitb_10.42.42.1(pid=20304): Terminating (SIGINT) [trial-19↪osmo-nitb_10.42.42.1(pid=20304)] [process.py:106]
I would bet this is an ofono bug in which they announce the interfaces before enabling them on the bus. Needs to be checked.
Updated by pespin almost 7 years ago
- Assignee set to 118
Doesn't seem to be an issue in ofono, it looks like they are doing stuff in correct order.
So, this is probably an issue in our python code. Possibilities:
- We are not handling all the pending signals on time with poll()
- The dbus object (self._dbus_obj) is not updated correctly (only once at start) and then it may no be able to send methods for interfaces which were not there at the moment it was created.
Updated by neels almost 7 years ago
specifically the "MessageManager" interface seems to be missing for the first run after a modem was power cycled. If I restart the very same code again, it gets the MessageManager interface immediately.
We should investigate where in pydbus the KeyError exception is actually raised, and how that relates to actual DBus communication.
As a workaround, we could have a deferring loop that waits a while until all interfaces we'd like to use are actually fully present, instead of triggering on the announcement of an interface in the ofono specific 'Interfaces' property.
Updated by pespin almost 7 years ago
I saw the same behaviour described by Neels with other interfaces, for instance with the SimManager interface.
It seems the KeyError is hit the first time a dynamically allocated interface is allocated for a specific modem after ofono is started. Second time you access the iface (even if you power off the modem and power it up using ofono), the issue cannot be seen.
It seems to happen once for every modem, ie. the first time each of them is accessed.
Updated by neels almost 7 years ago
https://github.com/LEW21/pydbus/issues/56
pydbus uses 'Introspect' to discover what methods and such are available,
but it isn't going to re-evaluate the introspection arbitrarily.
IOW, if an interface did not exist when we created the Modem dbus_obj, despite the 'Introspection' result starting to have new items, pydbus won't suddenly have them appear in its internal CompositeObject thing taking track of what is available.
We need to exchange our dbus_obj, and then it should have the interfaces present:
pydbus has a way to create a new class on-the-fly and produce an instance of it. So it seems the only way is to make a new object instance.
https://github.com/LEW21/pydbus/blob/master/pydbus/proxy.py#L97
such an object is e.g.
DBUS.<CompositeObject>(org.ofono.Modem+org.ofono.VoiceCallManager+org.ofono.LocationReporting+org.ofono.SimManager+org.freedesktop.DBus.Introspectable)'> type(self).__bases__ (<class 'DBUS.org.ofono.Modem'>, <class 'DBUS.org.ofono.VoiceCallManager'>, <class 'DBUS.org.ofono.LocationReporting'>, <class 'DBUS.org.ofono.SimManager'>, <class 'DBUS.org.freedesktop.DBus.Introspectable'>)
We have to run all of the _on_interface_enabled() all over every time to re-connect signals to the new objects.
Updated by pespin almost 7 years ago
I guess we can either mark this task as In Progress, Feedback or Resolved, as the patch with the workaround is already merged. I think having it in feedback for a while to monitor the issue on pydbus side can be helpful.
Updated by neels almost 7 years ago
- Status changed from New to Resolved
forgot to update the status, sorry.
We work around this problem by https://gerrit.osmocom.org/2733.
On the upstream pydbus project, there is no response yet on the issue about this.
