Cellular Network Infrastructure

From time to time, tests checking SMS Delivery Receipts in osmo-gsm-tester fail due to receiving a DeliverSM with an unexpected user_message_reference value.

The issue seems to be present both in osmo-nitb and in new osmo-msc, when running osmo-gsm-tester test esme_ms_sms_storeforward.py.

The issue is spotted in https://jenkins.osmocom.org/jenkins/view/osmo-gsm-tester/job/osmo-gsm-tester_run/3042/, I'll upload the test tgz output in here.

In both osmo-msc and osmo-nitb, the isse is the following:

00:23:39.121625 tst   esme_ms_sms_storeforward.py:55: checking MS can receive SMS while registered...  [trial-3042↪aoip_smpp↪esme_ms_sms_storeforward.py:55]  [esme_ms_sms_storeforward.py:55]
00:23:39.302422 tst                       esme-24924: Sending SMS "message nr. 14, smpp send already-registered message, from 24924, to 24925" to 24925  [trial-3042↪aoip_smpp↪esme-24924]  [esme.py:144]
00:23:39.339940 tst                       esme-24924: DBG: sent part with seq 4  [trial-3042↪aoip_smpp↪esme-24924]  [esme.py:162]
00:23:39.375312 tst                       esme-24924: DBG: pdus_pending: [4]  [trial-3042↪aoip_smpp↪esme-24924]  [esme.py:177]
00:23:39.412995 tst                       esme-24924: DBG: message sent resp with seq 4 , pdus_pending: [4]  [trial-3042↪aoip_smpp↪esme-24924]  [esme.py:169]
00:23:43.460011 tst                       esme-24924: DBG: message received: {seq=1517561744}  [trial-3042↪aoip_smpp↪esme-24924]  [esme.py:120]
00:23:43.496919 tst                       esme-24924: DBG: message received:  AlertNotification: {ms_availability_status='0'}  [trial-3042↪aoip_smpp↪esme-24924]  [esme.py:122]
00:23:44.539055 tst                        /sierra_2: Incoming SMS: 'message nr. 14, smpp send already-registered message, from 24924, to 24925'  [trial-3042↪aoip_smpp↪/sierra_2]  [ofono_client.py:547]
00:23:44.575626 tst                        /sierra_2: DBG: {info={LocalSentTime='2017-09-25T00:23:42+0200', Sender='+24924', SentTime='2017-09-25T00:23:42+0200'}}  [trial-3042↪aoip_smpp↪/sierra_2]  [ofono_client.py:548]
00:23:44.612108 tst                        /sierra_2: SMS received as expected: 'message nr. 14, smpp send already-registered message, from 24924, to 24925'  [trial-3042↪aoip_smpp↪/sierra_2]  [ofono_client.py:554]
00:23:44.648968 tst                        /sierra_2: DBG: {info={LocalSentTime='2017-09-25T00:23:42+0200', Sender='+24924', SentTime='2017-09-25T00:23:42+0200'}}  [trial-3042↪aoip_smpp↪/sierra_2]  [ofono_client.py:555]
00:23:44.756595 tst   esme_ms_sms_storeforward.py:59: Waiting to receive and consume sms receipt with reference 2  [trial-3042↪aoip_smpp↪esme_ms_sms_storeforward.py:59]  [esme_ms_sms_storeforward.py:59]
00:23:49.950516 tst                       esme-24924: DBG: message received: {seq=1517561745}  [trial-3042↪aoip_smpp↪esme-24924]  [esme.py:120]
00:23:49.988599 tst                       esme-24924: DBG: message received: DeliverSM {references_pending_receipt=[2], user_message_reference=165}  [trial-3042↪aoip_smpp↪esme-24924]  [esme.py:125]
00:23:49.992277 tst   esme_ms_sms_storeforward.py:60: ERR: ValueError: list.remove(x): x not in list  [trial-3042↪aoip_smpp↪esme_ms_sms_storeforward.py:60]  [esme.py:126: self.references_pending_receipt.remove(umref)]

^ Expecting DeliverSM with user reference 2 but received 165

00:18:10.228228 tst   esme_ms_sms_storeforward.py:46: checking MS can receive SMS while registered...  [trial-3042↪smpp↪esme_ms_sms_storeforward.py:46]  [esme_ms_sms_storeforward.py:46]
00:18:10.419603 tst                       esme-24917: Sending SMS "message nr. 9, smpp send already-registered message, from 24917, to 24918" to 24918  [trial-3042↪smpp↪esme-24917]  [esme.py:144]
00:18:10.461079 tst                       esme-24917: DBG: sent part with seq 5  [trial-3042↪smpp↪esme-24917]  [esme.py:162]
00:18:10.498199 tst                       esme-24917: DBG: pdus_pending: [5]  [trial-3042↪smpp↪esme-24917]  [esme.py:177]
00:18:10.537632 tst                       esme-24917: DBG: message sent resp with seq 5 , pdus_pending: [5]  [trial-3042↪smpp↪esme-24917]  [esme.py:169]
00:18:13.584413 tst                       esme-24917: DBG: message received: {seq=1425383599}  [trial-3042↪smpp↪esme-24917]  [esme.py:120]
00:18:13.623841 tst                       esme-24917: DBG: message received: DeliverSM {references_pending_receipt=[3], user_message_reference=163}  [trial-3042↪smpp↪esme-24917]  [esme.py:125]
00:18:13.628528 tst   esme_ms_sms_storeforward.py:49: ERR: ValueError: list.remove(x): x not in list  [trial-3042↪smpp↪esme_ms_sms_storeforward.py:49]  [esme.py:126: self.references_pending_receipt.remove(umref)]

^ Expecting DeliverSM with user reference 3 but received 163

pcap file with RSL+OML+GSMTAP traffic for the test with osmo-nitb can be found inside the tgz in run.2017-09-25_00-05-22/smpp/esme_ms_sms_storeforward.py/osmo-nitb_10.42.42.2/pcap/. Traffic coming/going to the ESME is not recorded due to bug #2413. According to the osmo-gsm-tester logs, the python code implementing the ESME, the umref sent should be 3, but from what can be seen in the pcap file, the RP-Message Reference in GSMTAP is 0x0, and if I remember correctly we copy the SMPP ref to use the same value in the Um protocol, so they should be the same.

Still to check if the issue is related to following bits still missing in the osmo-gsm-tester esme implementation: #2452