Bug #2549
closedofono: Race condition / failure answering call
100%
Description
In osmo-gsm-tester, we maintain a list of calls which can be used by tests, and which is managed by CallAdded() and CallRemoved() from VoiceCallManager in ofono.
The test I'm writing, after both modems are registered, does the following:
mo_call_id = ms_mo.call_dial(ms_mt) # Calls ofono Dial() internally wait(lambda: mo_call_id in ms_mo.call_id_list()) wait(lambda: len(ms_mt.call_id_list()) > 0) mt_call_id = ms_mt.call_id_list()[0] ms_mt.call_answer(mt_call_id) # Calls ofono Answer() internally ms_mt.call_hangup(mt_call_id) # Calls ofono Hangup() internally wait(lambda: len(ms_mo.call_id_list()) == 0 and len(ms_mt.call_id_list()) == 0)
So, basically MO dials MT number and we wait until we see both modems have a VoiceCall object path in call_id_list().
However, if I run the test as shown above, it will fail in ofono Answer(). If I add a sleep(5) before calling Answer(), then it works. This is in my opinion a race condition which we should attempt to fix in ofono.
Here's the failure from osmo-gsm-tester log:
14:40:19.817323 tst /sierra_1: dialing: 10810 14:40:20.181912 tst /sierra_1: DBG: Adding /sierra_1/voicecall01 to call list 14:40:20.202362 tst /sierra_1: DBG: 'org.ofono.VoiceCallManager'.CallAdded() -> /si erra_1/voicecall01="{'Emergency': False, 'RemoteHeld': False, 'Multiparty': False, 'State': 'dialing', 'Li neIdentification': '10810', 'Name': '', 'RemoteMultiparty': False}" 14:40:20.220312 tst /sierra_1: Call already exists! 14:40:20.240115 tst /sierra_1: DBG: call_id_list: ['/sierra_1/voicecall01'] 14:40:20.259033 tst /sierra_1: DBG: 'org.ofono.VoiceCallManager'.CallRemoved() -> / sierra_1/voicecall01 14:40:20.278524 tst /sierra_2: DBG: call_id_list: [] 14:40:21.302711 tst /sierra_1: DBG: 'org.ofono.VoiceCallManager'.CallAdded() -> /si erra_1/voicecall01="{'Emergency': False, 'RemoteHeld': False, 'Multiparty': False, 'State': 'alerting', 'L ineIdentification': '10810', 'Name': '', 'RemoteMultiparty': False}" 14:40:21.324143 tst /sierra_2: DBG: call_id_list: [] 14:40:22.349817 tst /sierra_2: DBG: call_id_list: [] 14:40:23.382787 tst /sierra_2: DBG: 'org.ofono.VoiceCallManager'.CallAdded() -> /si erra_2/voicecall01="{'Emergency': False, 'RemoteHeld': False, 'Multiparty': False, 'State': 'dialing', 'Li neIdentification': '10809', 'Name': '', 'RemoteMultiparty': False}" 14:40:23.412998 tst /sierra_2: DBG: call_id_list: ['/sierra_2/voicecall01'] 14:40:23.431124 tst /sierra_2: DBG: call_id_list: ['/sierra_2/voicecall01'] 14:40:23.448467 tst /sierra_2: Answer call /sierra_2/voicecall01 14:40:23.459785 tst mo_mt_call.py:41: ERR: Error: g-io-error-quark: GDBus.Error:org.ofono. Error.Failed: Operation failed (36) [trial↪voice↪mo_mt_call.py:41] 14:40:23.468039 tst mo_mt_call.py:41: TRACEBACK: Traceback (most recent call last): File "/opt/pespin/osmo-gsm-tester/src/osmo_gsm_tester/suite.py", line 97, in run self.path) File "/opt/pespin/osmo-gsm-tester/src/osmo_gsm_tester/util.py", line 278, in run_python_file spec.loader.exec_module( importlib.util.module_from_spec(spec) ) File "<frozen importlib._bootstrap_external>", line 673, in exec_module File "<frozen importlib._bootstrap>", line 222, in _call_with_frames_removed File "/opt/pespin/osmo-gsm-tester/suites/voice/mo_mt_call.py", line 41, in <module> ms_mt.call_answer(mt_call_id) File "/opt/pespin/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 589, in call_answer call_dbus_obj.Answer() File "/usr/local/lib/python3.4/dist-packages/pydbus/proxy_method.py", line 75, in __call__ 0, timeout_to_glib(timeout), None).unpack() GLib.GError: g-io-error-quark: GDBus.Error:org.ofono.Error.Failed: Operation failed (36) [trial↪voice↪mo_mt_call.py:41]
Tested with:
/sierra_1: Manufacturer: 'Sierra Wireless, Incorporated', Model: 'MC7304', Revision: 'SWI9X15C_06
.03.32.04 r28324 CNSHZ-AR-BUILD 2015/05/25 01:09:15', Serial: '356853054230919'
/sierra_2: Manufacturer: 'Sierra Wireless, Incorporated', Model: 'MC7304', Revision: 'SWI9X15C_06
.03.32.04 r28324 CNSHZ-AR-BUILD 2015/05/25 01:09:15', Serial: '356853052645654'
Also what I find strange from the logs (both working and non-working scenario), is that MT (/sierra_2) creates a voiceCall object with state "dialing" instead of state "incoming". Even more strange because according to ofono documentation in Answer(), it should fail if state is not in "incoming" state.
https://git.kernel.org/pub/scm/network/ofono/ofono.git/tree/doc/voicecall-api.txt#n70
So, in summary:
- We should fix the race condition.
- state for /sierra_2 should be "incoming" instead of "dialing".
Related issues