Project

General

Profile

Actions

Bug #2456

closed

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

Added by pespin over 6 years ago. Updated almost 6 years ago.

Status:
Resolved
Priority:
Normal
Assignee:
Target version:
-
Start date:
08/21/2017
Due date:
% Done:

100%

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]

Files

trial-2282-run.tgz trial-2282-run.tgz 2.67 MB pespin, 08/21/2017 03:01 PM
trial-2325-run.tgz trial-2325-run.tgz 2.66 MB pespin, 08/23/2017 08:59 AM
trial-2389-run.tgz trial-2389-run.tgz 4.45 MB pespin, 08/25/2017 11:54 AM
ofono.log.txt ofono.log.txt 91.6 KB pespin, 08/25/2017 11:56 AM

Related issues

Related to OsmoGSMTester - Bug #2511: ofono: check all services for simple use before register race conditionResolved09/12/2017

Actions
Blocked by OsmoGSMTester - Bug #2576: include journal log `journalctl -o short-precise` to the test outputClosedpespin10/16/2017

Actions
Actions #1

Updated by pespin over 6 years ago

  • Assignee set to 55360
Actions #2

Updated by pespin over 6 years 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.

Actions #3

Updated by pespin over 6 years 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.

Actions #4

Updated by pespin over 6 years ago

  • Assignee changed from 55360 to lynxis
Actions #5

Updated by neels over 6 years ago

  • Priority changed from Normal to High
Actions #6

Updated by neels over 6 years 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?

Actions #7

Updated by lynxis over 6 years 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.

Actions #8

Updated by pespin over 6 years 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.

Actions #9

Updated by pespin over 6 years ago

As far as I can tell the issue seems to still be there after lynxis updated the modems + ofono in production env:

/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: '356853054228053'  [trial-3149↪aoip_sms:trx-sysmocell5000↪/sierra_2]  [ofono_client.py:564]
01:13:25.915166 tst                        /sierra_3: Manufacturer: 'Sierra Wireless, Incorporated', Model: 'MC7304', Revision: 'SWI9X15C_06.03.32.04 r28324 CNSHZ-AR-BUILD 2015/05/25 01:09:15', Serial: '356853054229028'  [trial-3149↪aoip_sms:trx-sysmocell5000↪/sierra_3]  [ofono_client.py:564]

lynxis can you confirm that's the expected new version of the firmware?

The failure is usually triggered during execution of test aoip_sms:trx-sysmocell5000.mo_mt_sms.py, but I've seen it on other tests too ( aoip_encryption:cipher-a50+cipher-a51.register_a5_1_authreq.py in build 3129).

Again, it seems modem states it is registered after being powered up without really checking the network. Then, after a while, it discovers it is actually not registered and status changes to "searching". I'd expect the modem to be in searching state since the start. If this cannot be fixed I'll try to apply the patch in osmo-gsm-tester explained in my previous post to this one.

Actions #10

Updated by pespin over 6 years ago

Ok, I have seen the same in job 3156 test "sms:sysmo.mo_mt_sms.py", it happens with both modems on the same test.

After fw+ofono upgrades, it seems the modem doesn't state it is registered, but in all tests I have seen so far failing after the upgrade, I see that somehow ofono is cancelling the Scan() dbus method around 200 ms after calling it. Well, actually I see the Scan method is always cancelled. From the log on the same job, I can count "DBus method cancelled" string 15 times. I'd say something's wrong in ofono (perhaps osmo-gsm-tester) and we may want to have a look at it.

Actions #11

Updated by pespin over 6 years ago

The cancelled method issue is fixed and merged in https://gerrit.osmocom.org/#/c/4145/ . However, I still see test aoip_sms:trx-sysmocell5000.mo_mt_sms.py failing. It can clearly be seen how /sierra_3 states it is in state "registered" when powered on, and then after a while it realizes it is not registered and switches to state "searching", and then it never registers automatically (without calling Register because we were initially told that we were already registered):

                 /sierra_3: DBG: Powered == False  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:301]
01:13:24.890842 tst                        /sierra_3: DBG: Powering on  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3]  [ofono_client.py:516]
01:13:24.931744 bus                        /sierra_3: Setting Powered True  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:309]
01:13:25.171986 bus                        /sierra_3: DBG: Powered == True  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:301]
01:13:25.217578 bus                        /sierra_3: DBG: 'org.ofono.Modem'.PropertyChanged() -> Powered=True  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:228]
01:13:25.261972 bus                        /sierra_3: DBG: interface enabled: org.ofono.VoiceCallManager  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:241]
01:13:25.303559 bus                        /sierra_3: DBG: 'org.ofono.Modem'.PropertyChanged() -> Features=[]  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:228]
01:13:25.345046 bus                        /sierra_3: Setting Online True  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:309]
01:13:25.511021 bus                        /sierra_3: DBG: 'org.ofono.Modem'.PropertyChanged() -> Manufacturer=Sierra Wireless, Incorporated  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:228]
01:13:25.550744 bus                        /sierra_3: DBG: interface enabled: org.ofono.LocationReporting  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:241]
01:13:25.591930 bus                        /sierra_3: DBG: 'org.ofono.Modem'.PropertyChanged() -> Features=['gps']  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:228]
01:13:25.631702 bus                        /sierra_3: DBG: 'org.ofono.Modem'.PropertyChanged() -> Model=MC7304  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:228]
01:13:25.671594 bus                        /sierra_3: DBG: interface enabled: org.ofono.SimManager  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:241]
01:13:25.711837 bus                        /sierra_3: DBG: 'org.ofono.Modem'.PropertyChanged() -> Features=['sim', 'gps']  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:228]
01:13:25.752355 bus                        /sierra_3: DBG: 'org.ofono.Modem'.PropertyChanged() -> Revision=SWI9X15C_06.03.32.04 r28324 CNSHZ-AR-BUILD 2015/05/25 01:09:15  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:228]
01:13:25.792305 bus                        /sierra_3: DBG: 'org.ofono.Modem'.PropertyChanged() -> Online=True  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:228]
01:13:25.851977 bus                        /sierra_3: DBG: Online == True  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:301]
01:13:25.891704 bus                        /sierra_3: DBG: 'org.ofono.Modem'.PropertyChanged() -> Serial=356853054229028  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:228]
01:13:25.929832 bus                        /sierra_3: DBG: has_interface(org.ofono.NetworkRegistration, org.ofono.MessageManager) == False  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:293]
01:13:26.985243 bus                        /sierra_3: DBG: interface enabled: org.ofono.AllowedAccessPoints  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:241]
01:13:27.024961 bus                        /sierra_3: DBG: 'org.ofono.Modem'.PropertyChanged() -> Features=['sim', 'gps']  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:228]
01:13:27.067673 bus                        /sierra_3: DBG: interface enabled: org.ofono.SupplementaryServices  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:241]
01:13:27.108275 bus                        /sierra_3: DBG: 'org.ofono.Modem'.PropertyChanged() -> Features=['ussd', 'sim', 'gps']  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:228]
01:13:27.147524 bus                        /sierra_3: DBG: interface enabled: org.ofono.ConnectionManager  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:241]
01:13:27.190942 bus                        /sierra_3: DBG: 'org.ofono.Modem'.PropertyChanged() -> Features=['gprs', 'ussd', 'sim', 'gps']  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:228]
01:13:27.231882 bus                        /sierra_3: DBG: interface enabled: org.ofono.RadioSettings  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:241]
01:13:27.271344 bus                        /sierra_3: DBG: 'org.ofono.Modem'.PropertyChanged() -> Features=['rat', 'gprs', 'ussd', 'sim', 'gps']  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:228]
01:13:27.313771 bus                        /sierra_3: DBG: interface enabled: org.ofono.NetworkRegistration  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:241]
01:13:27.354710 bus                        /sierra_3: DBG: Connecting 1 signals for org.ofono.NetworkRegistration  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:281]
01:13:27.425251 bus                        /sierra_3: DBG: 'org.ofono.Modem'.PropertyChanged() -> Features=['net', 'rat', 'gprs', 'ussd', 'sim', 'gps']  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:228]
01:13:27.468471 bus                        /sierra_3: DBG: has_interface(org.ofono.NetworkRegistration, org.ofono.MessageManager) == False  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:293]
01:13:28.517565 bus                        /sierra_3: DBG: interface enabled: org.ofono.MessageManager, org.ofono.PushNotification, org.ofono.SmartMessaging  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:241]
01:13:28.558075 bus                        /sierra_3: DBG: Connecting 1 signals for org.ofono.MessageManager  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:281]
01:13:28.626869 bus                        /sierra_3: DBG: 'org.ofono.Modem'.PropertyChanged() -> Features=['sms', 'net', 'rat', 'gprs', 'ussd', 'sim', 'gps']  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:228]
01:13:28.666998 tst                        /sierra_3: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Strength=60  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3]  [ofono_client.py:418]
01:13:28.706901 bus                        /sierra_3: DBG: has_interface(org.ofono.NetworkRegistration, org.ofono.MessageManager) == True  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3↪/sierra_3]  [ofono_client.py:293]
01:13:28.752964 tst                        /sierra_3: DBG: status: registered  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3]  [ofono_client.py:424]
01:13:28.791637 tst                        /sierra_3: Already registered with ('901', '70')  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3]  [ofono_client.py:530]
01:13:28.840337 tst                        /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: '356853054228053'  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_2]  [ofono_client.py:566]
01:13:28.889281 tst                        /sierra_3: Manufacturer: 'Sierra Wireless, Incorporated', Model: 'MC7304', Revision: 'SWI9X15C_06.03.32.04 r28324 CNSHZ-AR-BUILD 2015/05/25 01:09:15', Serial: '356853054229028'  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3]  [ofono_client.py:566]
01:13:29.002684 tst                  mo_mt_sms.py:32: waiting for modems to attach...  [trial-3182↪aoip_sms:trx-sysmocell5000↪mo_mt_sms.py:32]  [mo_mt_sms.py:32]
01:13:29.194437 tst                        /sierra_3: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Name=90170  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3]  [ofono_client.py:418]
01:13:29.240648 tst                        /sierra_2: DBG: status: searching  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_2]  [ofono_client.py:424]
01:13:30.282002 tst                        /sierra_3: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Status=searching  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3]  [ofono_client.py:418]
01:13:30.319388 tst                        /sierra_3: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Name=  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_3]  [ofono_client.py:418]
01:13:30.367461 tst                        /sierra_2: DBG: status: searching  [trial-3182↪aoip_sms:trx-sysmocell5000↪/sierra_2]  [ofono_client.py:424]
Actions #12

Updated by pespin over 6 years ago

  • Related to Bug #2511: ofono: check all services for simple use before register race condition added
Actions #13

Updated by pespin over 6 years ago

Forcing osmo-gsm-tester to always re-scan after power on even if the modem already states it's registered helps improve the situation (lower error rate) but errors can still be seen from time to time.
It seems the patch writen by lynxis to address this issue was still not deployed. Let's see how it behaves after that.

Actions #14

Updated by pespin over 6 years ago

  • Status changed from In Progress to Stalled
Actions #15

Updated by pespin over 6 years ago

  • Blocked by Bug #2576: include journal log `journalctl -o short-precise` to the test output added
Actions #16

Updated by lynxis over 6 years ago

  • Assignee changed from lynxis to pespin

pespin is working on implementing different LAC codes for every test. It might fix the problem.

Actions #17

Updated by pespin over 6 years ago

  • Status changed from Stalled to Feedback

Changing LAC has been added a while ago and I think this issues look a lot better in terms of frequency, but I'm not sure if we are still avoid them. Let's wait a bit more to see if I can catch the issue again, otherwise we can close it at some point.

Actions #18

Updated by laforge about 6 years ago

  • Priority changed from High to Normal
Actions #19

Updated by pespin almost 6 years ago

  • Status changed from Feedback to Resolved
  • % Done changed from 40 to 100

I don't recall seeing this issue regularly anymore, we can close it.

Actions

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)