Project

General

Profile

Bug #2285

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

Added by neels 6 months ago. Updated about 1 month ago.

Status:
Closed
Priority:
Urgent
Assignee:
Target version:
-
Start date:
05/22/2017
Due date:
% Done:

100%

Resolution:

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.

trial-2384-run.tgz (4.41 MB) pespin, 08/25/2017 12:44 PM

History

#1 Updated by neels 6 months 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"

#2 Updated by neels 6 months ago

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

#3 Updated by neels 6 months 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

#4 Updated by pespin 3 months 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.

#5 Updated by pespin 3 months ago

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

#6 Updated by neels 3 months ago

  • Priority changed from Normal to Urgent

#7 Updated by neels 3 months ago

causes sporadic failure on the osmo-gsm-tester

#8 Updated by neels 2 months ago

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

#9 Updated by neels 2 months ago

  • Status changed from In Progress to Resolved
  • % Done changed from 90 to 100

merged.

#10 Updated by laforge about 1 month ago

  • Status changed from Resolved to Closed

Also available in: Atom PDF