Cellular Network Infrastructure » Core Network (CN) » OsmoMSC

22:42:13 run              osmo-msc_10.42.42.3: DBG: attached: GET_REPLY 0 subscriber-list-active-v1 901700000009029,1145 
22:42:14 bus Ctrl(host='10.42.42.3', port=4255): DBG: Connecting
22:42:14 bus Ctrl(host='10.42.42.3', port=4255): DBG: Sending {data='GET 0 subscriber-list-active-v1'}
22:42:14 bus Ctrl(host='10.42.42.3', port=4255): DBG: Disconnecting
22:42:15 run              osmo-msc_10.42.42.3: DBG: attached: GET_REPLY 0 subscriber-list-active-v1 901700000009029,1145 
22:42:16 bus Ctrl(host='10.42.42.3', port=4255): DBG: Connecting
22:42:16 bus Ctrl(host='10.42.42.3', port=4255): DBG: Sending {data='GET 0 subscriber-list-active-v1'}
22:42:16 bus Ctrl(host='10.42.42.3', port=4255): DBG: Disconnecting
22:42:16 run              osmo-msc_10.42.42.3: DBG: attached: GET_REPLY 0 subscriber-list-active-v1 901700000009029,1145 
22:42:17 bus Ctrl(host='10.42.42.3', port=4255): DBG: Connecting
22:42:17 bus Ctrl(host='10.42.42.3', port=4255): DBG: Sending {data='GET 0 subscriber-list-active-v1'}
22:42:17 bus Ctrl(host='10.42.42.3', port=4255): DBG: Disconnecting
22:42:17 run              osmo-msc_10.42.42.3: DBG: attached: GET_REPLY 0 subscriber-list-active-v1 901700000009029,1145 , 
22:42:18 bus Ctrl(host='10.42.42.3', port=4255): DBG: Connecting
22:42:18 bus Ctrl(host='10.42.42.3', port=4255): DBG: Sending {data='GET 0 subscriber-list-active-v1'}
22:42:18 bus Ctrl(host='10.42.42.3', port=4255): DBG: Disconnecting
22:42:18 run              osmo-msc_10.42.42.3: DBG: attached: GET_REPLY 0 subscriber-list-active-v1 901700000009029,1145 901700000009031,1144 

• Note the listing being "901700000009029,1145" a couple of times;
• then once "901700000009029,1145 ," with that odd comma all alone;
• next time the second modem is attached properly: "901700000009029,1145 901700000009031,1144"

Also ensure that listed subscribers indeed are really attached, with Location Updating having completed successfully.

In an osmo-gsm-tester run we saw that a NITB responds with an IMSI being attached, while the modem returns its attached state only about 5 seconds later (which should have been less than one second maximum).

17:11:32 tst                        /sierra_1: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Strength=40
17:11:32 bus Ctrl(host='10.42.42.2', port=4249): DBG: Connecting
17:11:32 bus Ctrl(host='10.42.42.2', port=4249): DBG: Sending {data='GET 0 subscriber-list-active-v1'}
17:11:32 bus Ctrl(host='10.42.42.2', port=4249): DBG: Disconnecting
17:11:32 run             osmo-nitb_10.42.42.2: DBG: attached: GET_REPLY 0 subscriber-list-active-v1 901700000009031,1609 901700000009029,1610
17:11:37 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Status=searching
17:11:38 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Status=registered
17:11:38 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> LocationAreaCode=23
17:11:38 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> CellId=0
17:11:38 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Name=901-70
17:11:38 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> MobileCountryCode=901
17:11:38 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> MobileNetworkCode=70
17:11:38 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Strength=40

This can be reproduced in osmo-gsm-tester test aoip_encryption.register_a5_0_authreq.py quite frequently since we added it last night. It shows up about 1/4 of the times the test is run.

I attach a run tar.gz from osmo-gsm-tester showing the issue. It's interesting to have a look at run.2017-08-25_08-05-25/aoip_encryption/register_a5_0_authreq.py/osmo-bsc_10.42.42.5/pcap/ which contains a pcap with GSMTAP.

That test basically does the following (until it failure):
- set "encryption a5 0" for both MSC and BSC (encryption off)
- set "authentication required" for MSC.
- subscribe an MS with a wrong KI in order to validate that it won't be able to authenticate correctly.
- To validate that, following line is run: assert not msc.subscriber_attached(ms)
- Mentioned assertion fails.

osmo-gsm-tester shows the following (debug log):

08:24:40.013578 tst                        /sierra_2: DBG: scanned operators:  [('/sierra_2/operator/90170', {'Technologies': ['gsm'], 'Status': 'available', 'Name': '901-70', 'MobileNetworkCode': '70', 'MobileCountryCode': '901'}), ('/sierra_2/operator/26201', {'Technologies': ['gsm', 'umts', 'lte'], 'Status': 'forbidden', 'Name': 'TDG', 'MobileNetworkCode': '01', 'MobileCountryCode': '262'}), ('/sierra_2/operator/26202', {'Technologies': ['gsm', 'umts', 'lte'], 'Status': 'forbidden', 'Name': 'Vodafone', 'MobileNetworkCode': '02', 'MobileCountryCode': '262'}), ('/sierra_2/operator/26203', {'Technologies': ['umts', 'lte'], 'Status': 'forbidden', 'Name': 'E-Plus', 'MobileNetworkCode': '03', 'MobileCountryCode': '262'})]  [trial-2384↪aoip_encryption↪/sierra_2]  [ofono_client.py:469]
08:24:40.055616 tst                        /sierra_2: Registering with operator /sierra_2/operator/90170 ('901', '70')  [trial-2384↪aoip_encryption↪/sierra_2]  [ofono_client.py:488]
08:24:41.135290 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Status=unregistered  [trial-2384↪aoip_encryption↪/sierra_2]  [ofono_client.py:410]
08:24:42.182137 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Technology=gsm  [trial-2384↪aoip_encryption↪/sierra_2]  [ofono_client.py:410]
08:24:42.220789 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Status=registered  [trial-2384↪aoip_encryption↪/sierra_2]  [ofono_client.py:410]
08:24:42.259445 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> LocationAreaCode=23  [trial-2384↪aoip_encryption↪/sierra_2]  [ofono_client.py:410]
08:24:42.297073 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> CellId=0  [trial-2384↪aoip_encryption↪/sierra_2]  [ofono_client.py:410]
08:24:42.336055 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Name=901-70  [trial-2384↪aoip_encryption↪/sierra_2]  [ofono_client.py:410]
08:24:42.373567 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> MobileCountryCode=901  [trial-2384↪aoip_encryption↪/sierra_2]  [ofono_client.py:410]
08:24:42.410300 tst                        /sierra_2: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> MobileNetworkCode=70  [trial-2384↪aoip_encryption↪/sierra_2]  [ofono_client.py:410]
08:24:42.517567 tst      register_a5_0_authreq.py:35: Asserting modem did not register  [trial-2384↪aoip_encryption↪register_a5_0_authreq.py:35]  [register_a5_0_authreq.py:35]
08:24:42.698434 bus Ctrl(host='10.42.42.4', port=4255): DBG: Connecting  [trial-2384↪aoip_encryption↪osmo-msc_10.42.42.4↪CTRL(10.42.42.4:4255)↪Ctrl(host='10.42.42.4', port=4255)]  [osmo_ctrl.py:54]
08:24:42.734832 bus Ctrl(host='10.42.42.4', port=4255): DBG: Sending {data='GET 0 subscriber-list-active-v1'}  [trial-2384↪aoip_encryption↪osmo-msc_10.42.42.4↪CTRL(10.42.42.4:4255)↪Ctrl(host='10.42.42.4', port=4255)]  [osmo_ctrl.py:65]
08:24:42.771819 bus Ctrl(host='10.42.42.4', port=4255): DBG: Receiving {data=b'\x008\xee\x00GET_REPLY 0 subscriber-list-active-v1 901700000015252,\n'}  [trial-2384↪aoip_encryption↪osmo-msc_10.42.42.4↪CTRL(10.42.42.4:4255)↪Ctrl(host='10.42.42.4', port=4255)]  [osmo_ctrl.py:71]
08:24:42.807544 bus Ctrl(host='10.42.42.4', port=4255): DBG: Disconnecting  [trial-2384↪aoip_encryption↪osmo-msc_10.42.42.4↪CTRL(10.42.42.4:4255)↪Ctrl(host='10.42.42.4', port=4255)]  [osmo_ctrl.py:60]
08:24:42.842282 run              osmo-msc_10.42.42.4: DBG: attached: GET_REPLY 0 subscriber-list-active-v1 901700000015252,   [trial-2384↪aoip_encryption↪osmo-msc_10.42.42.4]  [osmo_msc.py:124]
08:24:42.844884 tst      register_a5_0_authreq.py:38: ERR: AssertionError: register_a5_0_authreq.py:38: assert not msc.subscriber_attached(ms)  [trial-2384↪aoip_encryption↪register_a5_0_authreq.py:38]  [register_a5_0_authreq.py:38: assert not msc.subscriber_attached(ms)]

As you can see, subscriber-list-active-v1 shows IMSI but no msisdn, as explained in previous comments. Nevertheless, It shows that the subscriber is available.

However pcap file from bsc shows that Authentication Response is rejected (expected, because the used KI to generate the response in HLR is not the correct one). This means subscriber-list-active-v1 should never return that subscriber when called.

Sorry I forgot to attach the tar.gz, here it is

causes sporadic failure on the osmo-gsm-tester

https://gerrit.osmocom.org/3898

merged.