Bug #2285: ctrl: list-active-subscribers may return an "empty" subsciber - OsmoMSC - Open Source Mobile Communications

Custom queries

all-by-project

Actions

Copy link

Bug #2285

closed

ctrl: list-active-subscribers may return an "empty" subsciber

Added by neels almost 7 years ago. Updated over 6 years ago.

Status:

Closed

Priority:

Urgent

Assignee:

neels

Category:

Target version:

Start date:

05/22/2017

Due date:

% Done:

100%

Resolution:

Spec Reference:

Description

In osmo-gsm-tester I had a loop polling CTRL command list-active-subscribers every second.
There seems to be a short time during subscriber attach where a subscriber is listed without IMSI or phone number, i.e. where <imsi>,<msisdn> becomes just ",".
Fix this CTRL command to list exactly valid and active subscribers (probably related to new VLR code). Screenshot in following comment.

Files

trial-2384-run.tgz

4.41 MB

pespin, 08/25/2017 12:44 PM

History
Notes
Property changes

Actions

Copy link

Updated by neels almost 7 years ago

Assignee set to neels

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"

Actions

Copy link

Updated by neels almost 7 years ago

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

Actions

Copy link

Updated by neels almost 7 years ago

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

Actions

Copy link

Updated by pespin over 6 years ago

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.

Actions

Copy link