Cellular Network Infrastructure » OsmoGSMTester

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".