urfkill does not wait for modem to be powered to online it

[Alfonso Sanchez-Beato]

Some times (quite often) urfkill fails to set the Online property with failure

<warning> Could not set Online property in oFono: GDBus.Error:org.ofono.Error.NotAvailable: Operation currently not available

Taking a look at ofono code, this is returned in case the modem Powered property is not true. The warning happens because urfkill tries to set Online too fast, before the mode has set itself as powered. To solve this, urfkill should wait for the Powered property to be true before trying to set Online.

In the end urfkill is able to Online the modem because set_soft() is called twice for the device:

Oct 8 07:56:51 ubuntu-phablet URfkill[1097]: Setting device 100 (WWAN) to unblocked
Oct 8 07:56:51 ubuntu-phablet URfkill[1097]: set_soft: Setting WWAN to unblocked
Oct 8 07:56:51 ubuntu-phablet URfkill[1097]: Modem found: '/ril_0'
Oct 8 07:56:51 ubuntu-phablet URfkill[1097]: Setting device 101 (WWAN) to unblocked
Oct 8 07:56:51 ubuntu-phablet URfkill[1097]: set_soft: Setting WWAN to unblocked
Oct 8 07:56:51 ubuntu-phablet URfkill[1097]: device_changed_cb: unknown unknown
Oct 8 07:56:51 ubuntu-phablet URfkill[1097]: <warning> Could not set Online property in oFono: GDBus.Error:org.ofono.Error.NotAvailable: Operation currently not available
Oct 8 07:56:51 ubuntu-phablet URfkill[1097]: device_changed_cb: unknown unknown
Oct 8 07:56:51 ubuntu-phablet URfkill[1097]: <warning> Could not set Online property in oFono: GDBus.Error:org.ofono.Error.NotAvailable: Operation currently not available
Oct 8 07:56:53 ubuntu-phablet URfkill[1097]: modem_signal_cb: calling set_soft block: 0
Oct 8 07:56:53 ubuntu-phablet URfkill[1097]: set_soft: Setting WWAN to unblocked
Oct 8 07:56:53 ubuntu-phablet URfkill[1097]: modem_signal_cb: calling set_soft block: 0
Oct 8 07:56:53 ubuntu-phablet URfkill[1097]: set_soft: Setting WWAN to unblocked

thing that also needs to be investigated.

[Alfonso Sanchez-Beato (alfonsosanchezbeato)]

Taking a look at urfkill code, it tries to online the modem right after detecting a modem, and after receiving a change of the Powered property in the device-ofono code, so although annoying the warning is not such a big issue.

[Alfonso Sanchez-Beato (alfonsosanchezbeato)]

I have seen that in some cases if urfkill is a bit slower that ofono you can get an InProgress error instead of NotAvailable, which might be an actual bug. In this case, the first call to set Online property succeeds, and the second one returns the InProgress error. Looking at logs from

https://bugs.launchpad.net/ubuntu/+source/urfkill/+bug/1388065

you see

Oct 31 07:09:59 ubuntu-phablet URfkill[4496]: set_soft: Setting WWAN to unblocked
Oct 31 07:09:59 ubuntu-phablet URfkill[4496]: Modem found: '/ril_0'
Oct 31 07:09:59 ubuntu-phablet URfkill[4496]: Setting device 101 (WWAN) to unblocked
Oct 31 07:09:59 ubuntu-phablet URfkill[4496]: set_soft: Setting WWAN to unblocked
Oct 31 07:09:59 ubuntu-phablet URfkill[4496]: set_soft: Setting WWAN to unblocked
Oct 31 07:09:59 ubuntu-phablet URfkill[4496]: device_changed_cb: Fake Manufacturer Fake Modem Model
Oct 31 07:09:59 ubuntu-phablet URfkill[4496]: set_soft: Setting WWAN to unblocked
Oct 31 07:09:59 ubuntu-phablet URfkill[4496]: device_changed_cb: Fake Manufacturer Fake Modem Model
Oct 31 07:09:59 ubuntu-phablet URfkill[4496]: <warning> Could not set Online property in oFono: GDBus.Error:org.ofono.Error.InProgress: Operation already in progress
Oct 31 07:09:59 ubuntu-phablet URfkill[4496]: <warning> Could not set Online property in oFono: GDBus.Error:org.ofono.Error.InProgress: Operation already in progress

[Alfonso Sanchez-Beato (alfonsosanchezbeato)]

A look at URfkill code shows that even the InProgress error in the second call should be innocuous, as there is no GTask for it and we know the current state tracking ofono's "Online" property.