Project

General

Profile

Bug #2456

ofono: OsmGsmTester tests fail due to SierraW modem stating it is registered but it's not

Added by pespin 30 days ago. Updated 6 days ago.

Status:
In Progress
Priority:
High
Assignee:
Target version:
-
Start date:
08/21/2017
Due date:
% Done:

40%

Spec Reference:

Description

From time to time some tests fail with a Wait Timeout waiting for NITB to see the subscriber registered. Previous to that, ofono already stated it is registered by sending a signal. However, looking at the pcap file which contains both RSL/OML and GSMTAP, no uplink traffic is seen, which means the modem didn't register at all despite signalling upper layers that it did so.

I attach a run directory containing all information from failed run. Unfortunately there's no ofonod debug output from that time as the log buffer already wrapped (it can store around 12 hours). Let's follow recent run failures to be able to catch same issue and get some systemd ofono logs.

Have a look at log from test smpp/esme_ms_sms_storeforward.py. It first says it's registered, but actually notice that after a while the modem realizes it is not registered (sends a unregistered signal):

03:11:37.863810 tst   esme_ms_sms_storeforward.py:38: MS registers and will receive the SMS...  [trial-2282↪smpp↪esme_ms_sms_storeforward.py:38]  [esme_ms_sms_storeforward.py:38]
03:11:38.046333 bus                        /sierra_2: DBG: Powered == False  [trial-2282↪smpp↪/sierra_2↪/sierra_2]  [ofono_client.py:290]
03:11:38.080832 tst                        /sierra_2: DBG: Powering on  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:490]
03:11:38.116390 bus                        /sierra_2: Setting Powered True  [trial-2282↪smpp↪/sierra_2↪/sierra_2]  [ofono_client.py:298]
03:11:38.381358 bus                        /sierra_2: DBG: Powered == True  [trial-2282↪smpp↪/sierra_2↪/sierra_2]  [ofono_client.py:290]
03:11:38.421259 bus                        /sierra_2: DBG: interface enabled: org.ofono.VoiceCallManager  [trial-2282↪smpp↪/sierra_2↪/sierra_2]  [ofono_client.py:230]
03:11:38.459498 bus                        /sierra_2: Setting Online True  [trial-2282↪smpp↪/sierra_2↪/sierra_2]  [ofono_client.py:298]
03:11:38.704361 bus                        /sierra_2: DBG: interface enabled: org.ofono.LocationReporting  [trial-2282↪smpp↪/sierra_2↪/sierra_2]  [ofono_client.py:230]
03:11:38.748423 bus                        /sierra_2: DBG: interface enabled: org.ofono.SimManager  [trial-2282↪smpp↪/sierra_2↪/sierra_2]  [ofono_client.py:230]
03:11:38.808998 bus                        /sierra_2: DBG: Online == True  [trial-2282↪smpp↪/sierra_2↪/sierra_2]  [ofono_client.py:290]
03:11:38.846423 bus                        /sierra_2: DBG: has_interface(org.ofono.NetworkRegistration, org.ofono.MessageManager) == False  [trial-2282↪smpp↪/sierra_2↪/sierra_2]  [ofono_client.py:282]
03:11:39.895581 bus                        /sierra_2: DBG: interface enabled: org.ofono.AllowedAccessPoints  [trial-2282↪smpp↪/sierra_2↪/sierra_2]  [ofono_client.py:230]
03:11:39.932011 bus                        /sierra_2: DBG: interface enabled: org.ofono.RadioSettings  [trial-2282↪smpp↪/sierra_2↪/sierra_2]  [ofono_client.py:230]
03:11:39.971640 bus                        /sierra_2: DBG: interface enabled: org.ofono.SupplementaryServices  [trial-2282↪smpp↪/sierra_2↪/sierra_2]  [ofono_client.py:230]
03:11:40.008805 bus                        /sierra_2: DBG: interface enabled: org.ofono.ConnectionManager  [trial-2282↪smpp↪/sierra_2↪/sierra_2]  [ofono_client.py:230]
03:11:40.045589 bus                        /sierra_2: DBG: interface enabled: org.ofono.NetworkRegistration  [trial-2282↪smpp↪/sierra_2↪/sierra_2]  [ofono_client.py:230]
03:11:40.083931 bus                        /sierra_2: DBG: Connecting 1 signals for org.ofono.NetworkRegistration  [trial-2282↪smpp↪/sierra_2↪/sierra_2]  [ofono_client.py:270]
03:11:40.142561 bus                        /sierra_2: DBG: has_interface(org.ofono.NetworkRegistration, org.ofono.MessageManager) == True  [trial-2282↪smpp↪/sierra_2↪/sierra_2]  [ofono_client.py:282]
03:11:40.183012 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:11:40.219290 tst                        /sierra_2: Connect to ('901', '70')  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:504]
03:11:40.255470 tst                        /sierra_2: DBG: Scanning for operators...  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:423]
03:11:40.294597 bus                        /sierra_2: DBG: interface enabled: org.ofono.MessageManager, org.ofono.PushNotification, org.ofono.SmartMessaging  [trial-2282↪smpp↪/sierra_2↪/sierra_2]  [ofono_client.py:230]
03:11:40.330249 bus                        /sierra_2: DBG: Connecting 1 signals for org.ofono.MessageManager  [trial-2282↪smpp↪/sierra_2↪/sierra_2]  [ofono_client.py:270]
03:11:40.391233 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:11:41.433858 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:11:42.476459 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:11:43.519336 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:11:44.562620 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:11:45.606063 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:11:46.648742 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:11:47.692404 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:11:48.736202 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:11:49.779928 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:11:50.823520 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:11:51.867529 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:11:52.911455 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:11:53.955438 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:11:54.999443 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:11:56.043469 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:11:57.087498 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:11:58.131221 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:11:59.175230 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:12:00.219184 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:12:01.264592 tst                        /sierra_2: DBG: scanned operators:  [('/sierra_2/operator/26201', {'Technologies': ['gsm', 'umts', 'lte'], 'MobileCountryCode': '262', 'MobileNetworkCode': '01', 'Name': 'TDG', 'Status': 'forbidden'}), ('/sierra_2/operator/26202', {'Technologies': ['gsm', 'umts', 'lte'], 'MobileCountryCode': '262', 'MobileNetworkCode': '02', 'Name': 'Vodafone', 'Status': 'forbidden'}), ('/sierra_2/operator/26203', {'Technologies': ['umts', 'lte'], 'MobileCountryCode': '262', 'MobileNetworkCode': '03', 'Name': 'E-Plus', 'Status': 'forbidden'})]  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:460]
03:12:01.306003 tst                        /sierra_2: DBG: Failed to find Network Operator {attempts=1, mcc_mnc=('901', '70')}  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:475]
03:12:01.347308 tst                        /sierra_2: DBG: Scanning for operators...  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:423]
03:12:01.396006 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:12:02.441980 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:12:03.487441 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:12:04.532718 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:12:05.578179 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:12:06.622820 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:12:07.667553 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:12:08.711958 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:12:09.753956 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:12:10.795929 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:12:11.839169 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:12:12.881948 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:12:13.924756 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:12:14.968388 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:12:16.012097 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:12:17.055922 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:12:18.102185 tst                        /sierra_2: DBG: scanned operators:  [('/sierra_2/operator/90170', {'Technologies': ['gsm'], 'MobileCountryCode': '901', 'MobileNetworkCode': '70', 'Name': '901-70', 'Status': 'available'}), ('/sierra_2/operator/26201', {'Technologies': ['gsm', 'umts', 'lte'], 'MobileCountryCode': '262', 'MobileNetworkCode': '01', 'Name': 'TDG', 'Status': 'forbidden'}), ('/sierra_2/operator/26202', {'Technologies': ['gsm', 'umts', 'lte'], 'MobileCountryCode': '262', 'MobileNetworkCode': '02', 'Name': 'Vodafone', 'Status': 'forbidden'}), ('/sierra_2/operator/26203', {'Technologies': ['umts', 'lte'], 'MobileCountryCode': '262', 'MobileNetworkCode': '03', 'Name': 'E-Plus', 'Status': 'forbidden'})]  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:460]
03:12:18.143112 tst                        /sierra_2: Registering with operator /sierra_2/operator/90170 ('901', '70')  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:479]
03:12:18.215670 tst                        /sierra_2: DBG: status: searching  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:12:19.257158 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Status=unregistered  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:401]
03:12:19.296800 tst                        /sierra_2: DBG: status: unregistered  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:12:20.346340 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Technology=gsm  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:401]
03:12:20.386465 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Status=registered  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:401]
03:12:20.427324 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> LocationAreaCode=23  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:401]
03:12:20.467882 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> CellId=0  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:401]
03:12:20.507965 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Name=901-70  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:401]
03:12:20.546045 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> MobileCountryCode=901  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:401]
03:12:20.583831 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> MobileNetworkCode=70  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:401]
03:12:20.626724 tst                        /sierra_2: DBG: status: registered  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:407]
03:12:20.665008 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Strength=20  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:401]
03:12:20.703109 bus Ctrl(host='10.42.42.2', port=4249): DBG: Connecting  [trial-2282↪smpp↪osmo-nitb_10.42.42.2↪CTRL(10.42.42.2:4249)↪Ctrl(host='10.42.42.2', port=4249)]  [osmo_ctrl.py:54]
03:12:20.741230 bus Ctrl(host='10.42.42.2', port=4249): DBG: Sending {data='GET 0 subscriber-list-active-v1'}  [trial-2282↪smpp↪osmo-nitb_10.42.42.2↪CTRL(10.42.42.2:4249)↪Ctrl(host='10.42.42.2', port=4249)]  [osmo_ctrl.py:65]
03:12:20.784951 bus Ctrl(host='10.42.42.2', port=4249): DBG: Disconnecting  [trial-2282↪smpp↪osmo-nitb_10.42.42.2↪CTRL(10.42.42.2:4249)↪Ctrl(host='10.42.42.2', port=4249)]  [osmo_ctrl.py:60]
03:12:20.822511 run             osmo-nitb_10.42.42.2: DBG: attached: GET_REPLY 0 subscriber-list-active-v1   [trial-2282↪smpp↪osmo-nitb_10.42.42.2]  [osmo_nitb.py:118]

... CONTINUES IN A LOOP OF UNSUCCESSFUL GET_REPLY 0 HERE...

03:14:42.747906 bus Ctrl(host='10.42.42.2', port=4249): DBG: Connecting  [trial-2282↪smpp↪osmo-nitb_10.42.42.2↪CTRL(10.42.42.2:4249)↪Ctrl(host='10.42.42.2', port=4249)]  [osmo_ctrl.py:54]
03:14:42.783667 bus Ctrl(host='10.42.42.2', port=4249): DBG: Sending {data='GET 0 subscriber-list-active-v1'}  [trial-2282↪smpp↪osmo-nitb_10.42.42.2↪CTRL(10.42.42.2:4249)↪Ctrl(host='10.42.42.2', port=4249)]  [osmo_ctrl.py:65]
03:14:42.825492 bus Ctrl(host='10.42.42.2', port=4249): DBG: Disconnecting  [trial-2282↪smpp↪osmo-nitb_10.42.42.2↪CTRL(10.42.42.2:4249)↪Ctrl(host='10.42.42.2', port=4249)]  [osmo_ctrl.py:60]
03:14:42.860832 run             osmo-nitb_10.42.42.2: DBG: attached: GET_REPLY 0 subscriber-list-active-v1   [trial-2282↪smpp↪osmo-nitb_10.42.42.2]  [osmo_nitb.py:118]
03:14:43.900190 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Status=unregistered  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:401]
03:14:43.935199 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Name=  [trial-2282↪smpp↪/sierra_2]  [ofono_client.py:401]
03:14:43.970761 bus Ctrl(host='10.42.42.2', port=4249): DBG: Connecting  [trial-2282↪smpp↪osmo-nitb_10.42.42.2↪CTRL(10.42.42.2:4249)↪Ctrl(host='10.42.42.2', port=4249)]  [osmo_ctrl.py:54]
03:14:44.007028 bus Ctrl(host='10.42.42.2', port=4249): DBG: Sending {data='GET 0 subscriber-list-active-v1'}  [trial-2282↪smpp↪osmo-nitb_10.42.42.2↪CTRL(10.42.42.2:4249)↪Ctrl(host='10.42.42.2', port=4249)]  [osmo_ctrl.py:65]
03:14:44.048923 bus Ctrl(host='10.42.42.2', port=4249): DBG: Disconnecting  [trial-2282↪smpp↪osmo-nitb_10.42.42.2↪CTRL(10.42.42.2:4249)↪Ctrl(host='10.42.42.2', port=4249)]  [osmo_ctrl.py:60]
03:14:44.084060 run             osmo-nitb_10.42.42.2: DBG: attached: GET_REPLY 0 subscriber-list-active-v1   [trial-2282↪smpp↪osmo-nitb_10.42.42.2]  [osmo_nitb.py:118]
03:14:45.122783 bus Ctrl(host='10.42.42.2', port=4249): DBG: Connecting  [trial-2282↪smpp↪osmo-nitb_10.42.42.2↪CTRL(10.42.42.2:4249)↪Ctrl(host='10.42.42.2', port=4249)]  [osmo_ctrl.py:54]
03:14:45.158705 bus Ctrl(host='10.42.42.2', port=4249): DBG: Sending {data='GET 0 subscriber-list-active-v1'}  [trial-2282↪smpp↪osmo-nitb_10.42.42.2↪CTRL(10.42.42.2:4249)↪Ctrl(host='10.42.42.2', port=4249)]  [osmo_ctrl.py:65]
03:14:45.200845 bus Ctrl(host='10.42.42.2', port=4249): DBG: Disconnecting  [trial-2282↪smpp↪osmo-nitb_10.42.42.2↪CTRL(10.42.42.2:4249)↪Ctrl(host='10.42.42.2', port=4249)]  [osmo_ctrl.py:60]
03:14:45.236020 run             osmo-nitb_10.42.42.2: DBG: attached: GET_REPLY 0 subscriber-list-active-v1   [trial-2282↪smpp↪osmo-nitb_10.42.42.2]  [osmo_nitb.py:118]

... CONTINUES IN A LOOP OF UNSUCCESSFUL GET_REPLY 0 HERE...

03:17:21.009357 run             osmo-nitb_10.42.42.2: DBG: attached: GET_REPLY 0 subscriber-list-active-v1   [trial-2282↪smpp↪osmo-nitb_10.42.42.2]  [osmo_nitb.py:118]
03:17:21.012089 tst   esme_ms_sms_storeforward.py:41: ERR: Error: Wait timeout  [trial-2282↪smpp↪esme_ms_sms_storeforward.py:41]  [event_loop.py:61: raise log.Error('Wait timeout')]
03:17:21.017072 tst   esme_ms_sms_storeforward.py:41: TRACEBACK: Traceback (most recent call last):
  File "/home/jenkins/workspace/osmo-gsm-tester_run/osmo-gsm-tester/src/osmo_gsm_tester/suite.py", line 105, in run
    self.path)
  File "/home/jenkins/workspace/osmo-gsm-tester_run/osmo-gsm-tester/src/osmo_gsm_tester/util.py", line 282, in run_python_file
    SourceFileLoader(module_name, path).load_module()
  File "<frozen importlib._bootstrap>", line 539, in _check_name_wrapper
  File "<frozen importlib._bootstrap>", line 1614, in load_module
  File "<frozen importlib._bootstrap>", line 596, in _load_module_shim
  File "<frozen importlib._bootstrap>", line 1220, in load
  File "<frozen importlib._bootstrap>", line 1200, in _load_unlocked
  File "<frozen importlib._bootstrap>", line 1129, in _exec
  File "<frozen importlib._bootstrap>", line 1471, in exec_module
  File "<frozen importlib._bootstrap>", line 321, in _call_with_frames_removed
  File "/home/jenkins/workspace/osmo-gsm-tester_run/osmo-gsm-tester/suites/smpp/esme_ms_sms_storeforward.py", line 41, in <module>
    wait(nitb.subscriber_attached, ms)
  File "/home/jenkins/workspace/osmo-gsm-tester_run/osmo-gsm-tester/src/osmo_gsm_tester/test.py", line 47, in <lambda>
    wait = lambda *args, **kwargs: event_module.wait(suite_run, *args, **kwargs)
  File "/home/jenkins/workspace/osmo-gsm-tester_run/osmo-gsm-tester/src/osmo_gsm_tester/event_loop.py", line 61, in wait
    raise log.Error('Wait timeout')
osmo_gsm_tester.log.Error: Wait timeout
  [trial-2282↪smpp↪esme_ms_sms_storeforward.py:41]  [suite.py:148]
03:17:21.022051 tst   esme_ms_sms_storeforward.py:41: Test FAILED (376.8 sec)  [trial-2282↪smpp↪esme_ms_sms_storeforward.py:41]  [suite.py:149]

trial-2282-run.tgz (2.67 MB) pespin, 08/21/2017 03:01 PM

trial-2325-run.tgz (2.66 MB) pespin, 08/23/2017 08:59 AM

trial-2389-run.tgz (4.45 MB) pespin, 08/25/2017 11:54 AM

ofono.log.txt Magnifier (91.6 KB) pespin, 08/25/2017 11:56 AM

History

#1 Updated by pespin 30 days ago

  • Assignee set to osmo-gsm-tester

#2 Updated by pespin 28 days ago

Same issue happened again today in trial-2325. Again I was one hour late and systemd log from ofono was already gone. In this case tests sms/mo_mt_sms.py, and it seems it happened with both modems at the same time. Both show up as registered but no uplink packets in GSMTAP or RSL asking to register.

#3 Updated by pespin 26 days ago

Same issue appeared today in trial 2389. Luckily this time I catched it one hour after the issue so I have detailed ofono logs. I attach both output from osmo-gsm-tester (with pcaps) and the log of ofono during the time of the run of the entire test aoip_encryption/register_a5_0_authopt.py.

Error happened while running test aoip_encryption/register_a5_0_authopt.py. Check inside for pcap file in run.2017-08-25_12-09-22/aoip_encryption/register_a5_0_authopt.py/osmo-bsc_10.42.42.5/pcap/, it contains traces for GSMTAP.

The issue can be shown in time around 12:27:12. osmo-gsm-tester shows signal "registered" is received:

12:27:11.643147 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Status=unregistered  [trial-2389↪aoip_encryption↪/sierra_2]  [ofono_client.py:410]
12:27:11.683177 tst                        /sierra_2: DBG: status: unregistered  [trial-2389↪aoip_encryption↪/sierra_2]  [ofono_client.py:416]
12:27:12.724864 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Technology=gsm  [trial-2389↪aoip_encryption↪/sierra_2]  [ofono_client.py:410]
12:27:12.779390 tst                        /sierra_2: DBG: status: unregistered  [trial-2389↪aoip_encryption↪/sierra_2]  [ofono_client.py:416]
12:27:13.824099 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Status=registered  [trial-2389↪aoip_encryption↪/sierra_2]  [ofono_client.py:410]
12:27:13.862557 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> LocationAreaCode=23  [trial-2389↪aoip_encryption↪/sierra_2]  [ofono_client.py:410]
12:27:13.900370 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> CellId=0  [trial-2389↪aoip_encryption↪/sierra_2]  [ofono_client.py:410]
12:27:13.937971 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Name=901-70  [trial-2389↪aoip_encryption↪/sierra_2]  [ofono_client.py:410]
12:27:13.975569 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> MobileCountryCode=901  [trial-2389↪aoip_encryption↪/sierra_2]  [ofono_client.py:410]
12:27:14.013279 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> MobileNetworkCode=70  [trial-2389↪aoip_encryption↪/sierra_2]  [ofono_client.py:410]
12:27:14.050970 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Strength=20  [trial-2389↪aoip_encryption↪/sierra_2]  [ofono_client.py:410]
12:27:14.093997 tst                        /sierra_2: DBG: status: registered  [trial-2389↪aoip_encryption↪/sierra_2]  [ofono_client.py:416]

During the same time, here's the bits from ofonod:

ug 25 12:27:10.687777 testbed-production ofonod[732]: src/gprs.c:netreg_status_changed() 0
Aug 25 12:27:10.687799 testbed-production ofonod[732]: src/gprs.c:gprs_netreg_update() attach: 0, driver_attached: 0
Aug 25 12:27:12.543562 testbed-production ofonod[732]: drivers/qmimodem/network-registration.c:event_notify()
Aug 25 12:27:12.543603 testbed-production ofonod[732]: drivers/qmimodem/network-registration.c:event_notify() signal with -86 dBm on 4
Aug 25 12:27:12.607558 testbed-production ofonod[732]: drivers/qmimodem/network-registration.c:ss_info_notify()
Aug 25 12:27:12.607602 testbed-production ofonod[732]: drivers/qmimodem/network-registration.c:extract_ss_info()
Aug 25 12:27:12.607626 testbed-production ofonod[732]: drivers/qmimodem/network-registration.c:extract_ss_info() serving system status 0
Aug 25 12:27:12.607649 testbed-production ofonod[732]: drivers/qmimodem/network-registration.c:extract_ss_info() radio in use 4
Aug 25 12:27:12.607682 testbed-production ofonod[732]: drivers/qmimodem/network-registration.c:extract_ss_info() 901-70 (901:70)
Aug 25 12:27:12.607705 testbed-production ofonod[732]: drivers/qmimodem/network-registration.c:extract_ss_info() lac -1 cellid -1 tech 0
Aug 25 12:27:12.607730 testbed-production ofonod[732]: src/network.c:ofono_netreg_status_notify() /sierra_2 status 0 tech 0 lac -1 ci -1
Aug 25 12:27:12.607966 testbed-production ofonod[732]: src/network.c:current_operator_callback() 0x1882140, (nil)
Aug 25 12:27:12.607994 testbed-production ofonod[732]: src/gprs.c:netreg_status_changed() 0
Aug 25 12:27:12.608102 testbed-production ofonod[732]: src/gprs.c:gprs_netreg_update() attach: 0, driver_attached: 0
Aug 25 12:27:12.639551 testbed-production ofonod[732]: drivers/qmimodem/gprs.c:ss_info_notify()
Aug 25 12:27:12.639589 testbed-production ofonod[732]: drivers/qmimodem/gprs.c:handle_ss_info()
Aug 25 12:27:12.639610 testbed-production ofonod[732]: drivers/qmimodem/gprs.c:extract_ss_info()
Aug 25 12:27:12.639633 testbed-production ofonod[732]: drivers/qmimodem/gprs.c:extract_ss_info() radio in use 4
Aug 25 12:27:12.639658 testbed-production ofonod[732]: src/gprs.c:ofono_gprs_status_notify() /sierra_2 status 0
Aug 25 12:27:12.671543 testbed-production ofonod[732]: drivers/qmimodem/network-registration.c:event_notify()
Aug 25 12:27:12.671586 testbed-production ofonod[732]: drivers/qmimodem/network-registration.c:event_notify() rat 4 band 47 channel 868
Aug 25 12:27:12.735319 testbed-production ofonod[732]: drivers/qmimodem/network-registration.c:ss_info_notify()
Aug 25 12:27:12.735370 testbed-production ofonod[732]: drivers/qmimodem/network-registration.c:extract_ss_info()
Aug 25 12:27:12.735393 testbed-production ofonod[732]: drivers/qmimodem/network-registration.c:extract_ss_info() serving system status 1
Aug 25 12:27:12.735415 testbed-production ofonod[732]: drivers/qmimodem/network-registration.c:extract_ss_info() radio in use 4
Aug 25 12:27:12.735447 testbed-production ofonod[732]: drivers/qmimodem/network-registration.c:extract_ss_info() 901-70 (901:70)
Aug 25 12:27:12.735470 testbed-production ofonod[732]: drivers/qmimodem/network-registration.c:extract_ss_info() lac 23 cellid 0 tech 0
Aug 25 12:27:12.735495 testbed-production ofonod[732]: src/network.c:ofono_netreg_status_notify() /sierra_2 status 1 tech 0 lac 23 ci 0
Aug 25 12:27:12.735877 testbed-production ofonod[732]: drivers/qmimodem/network-registration.c:qmi_current_operator()
Aug 25 12:27:12.735902 testbed-production ofonod[732]: src/network.c:current_operator_callback() 0x1882140, (nil)
Aug 25 12:27:12.736654 testbed-production ofonod[732]: src/gprs.c:netreg_status_changed() 1
Aug 25 12:27:12.736681 testbed-production ofonod[732]: src/gprs.c:gprs_netreg_update() attach: 1, driver_attached: 0
Aug 25 12:27:12.736705 testbed-production ofonod[732]: drivers/qmimodem/gprs.c:qmi_set_attached() attached 1
Aug 25 12:27:12.736764 testbed-production ofonod[732]: drivers/qmimodem/network-registration.c:qmi_signal_strength()
Aug 25 12:27:12.740462 testbed-production ofonod[732]: src/gprs.c:netreg_status_changed() 1
Aug 25 12:27:12.740544 testbed-production ofonod[732]: src/gprs.c:gprs_netreg_update() attach: 1, driver_attached: 1
Aug 25 12:27:12.767557 testbed-production ofonod[732]: drivers/qmimodem/gprs.c:ss_info_notify()
Aug 25 12:27:12.767604 testbed-production ofonod[732]: drivers/qmimodem/gprs.c:handle_ss_info()
Aug 25 12:27:12.767625 testbed-production ofonod[732]: drivers/qmimodem/gprs.c:extract_ss_info()
Aug 25 12:27:12.767647 testbed-production ofonod[732]: drivers/qmimodem/gprs.c:extract_ss_info() radio in use 4
Aug 25 12:27:12.767671 testbed-production ofonod[732]: src/gprs.c:ofono_gprs_status_notify() /sierra_2 status 0
Aug 25 12:27:12.799601 testbed-production ofonod[732]: drivers/qmimodem/network-registration.c:event_notify()
Aug 25 12:27:12.799654 testbed-production ofonod[732]: drivers/qmimodem/network-registration.c:event_notify() rat 4 band 47 channel 868
Aug 25 12:27:12.863599 testbed-production ofonod[732]: drivers/qmimodem/network-registration.c:ss_info_notify()
Aug 25 12:27:12.863653 testbed-production ofonod[732]: drivers/qmimodem/network-registration.c:extract_ss_info()
Aug 25 12:27:12.863675 testbed-production ofonod[732]: drivers/qmimodem/network-registration.c:extract_ss_info() serving system status 1
Aug 25 12:27:12.863696 testbed-production ofonod[732]: drivers/qmimodem/network-registration.c:extract_ss_info() radio in use 4
Aug 25 12:27:12.863728 testbed-production ofonod[732]: drivers/qmimodem/network-registration.c:extract_ss_info() 901-70 (901:70)
Aug 25 12:27:12.863752 testbed-production ofonod[732]: drivers/qmimodem/network-registration.c:extract_ss_info() lac -1 cellid -1 tech 0
Aug 25 12:27:12.863777 testbed-production ofonod[732]: src/network.c:ofono_netreg_status_notify() /sierra_2 status 1 tech 0 lac -1 ci -1
Aug 25 12:27:12.863800 testbed-production ofonod[732]: drivers/qmimodem/network-registration.c:qmi_current_operator()
Aug 25 12:27:12.863822 testbed-production ofonod[732]: src/network.c:current_operator_callback() 0x1882140, 0x1897dd0
Aug 25 12:27:12.863852 testbed-production ofonod[732]: drivers/qmimodem/network-registration.c:qmi_signal_strength()
Aug 25 12:27:12.863909 testbed-production ofonod[732]: src/gprs.c:netreg_status_changed() 1
Aug 25 12:27:12.863931 testbed-production ofonod[732]: src/gprs.c:gprs_netreg_update() attach: 1, driver_attached: 1

As it can be seen, driver states it becomes attached, but GSMTAP from pcap file shows no activity during that time stating so. Also MSC states too that this modem is not registered.

#4 Updated by pespin 23 days ago

  • Assignee changed from osmo-gsm-tester to lynxis

#5 Updated by neels 13 days ago

  • Priority changed from Normal to High

#6 Updated by neels 11 days ago

I've been thinking. If we can't rely on the modem's "I am registered" state alone, we may want to also perform some action that guarantees we are registered. During own hw testing I like to do a USSD *#100# to see whether I am given an extension number to verify that I'm really registered. Our test scripts may have to do something like that to get conclusive results?

#7 Updated by lynxis 8 days ago

  • Status changed from New to In Progress
  • % Done changed from 0 to 40

I've created a patch and pushed it into sysmocom/lynxis/master. I'm waiting to test it.

#8 Updated by pespin 6 days ago

Let's see if this ofono fix solves the situation.
If it doesn't (due to some modem bug), then I just noticed that in osmo-gsm-tester, after powering on in connect() in ofono_client.py, we do the following check:

        if self.is_connected(mcc_mnc):
            self.log('Already registered with', mcc_mnc if mcc_mnc else 'default network')
            return

so as we see we are connected we avoid starting scan process (+ later Register()) to speedup the connection since we are already connected (according to ofono). If we are unable to fix the issue inside ofono, we could try if scanning in any case can help the modem realize it's really not connected.

Also available in: Atom PDF