Bug #2285
closedctrl: list-active-subscribers may return an "empty" subsciber
Added by neels almost 7 years ago. Updated over 6 years ago.
100%
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 | trial-2384-run.tgz | 4.41 MB | pespin, 08/25/2017 12:44 PM |
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"
Updated by neels almost 7 years ago
Also ensure that listed subscribers indeed are really attached, with Location Updating having completed successfully.
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
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.
Updated by pespin over 6 years ago
- File trial-2384-run.tgz trial-2384-run.tgz added
Sorry I forgot to attach the tar.gz, here it is
Updated by neels over 6 years ago
- Status changed from New to In Progress
- % Done changed from 0 to 90
Updated by neels over 6 years ago
- Status changed from In Progress to Resolved
- % Done changed from 90 to 100
merged.