Cellular Network Infrastructure » OsmoGSMTester

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.

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.

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?

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

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.

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.

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.

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]

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.

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

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.

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