Cellular Network Infrastructure » Radio Access Network » OsmoBSC

Test smpp.esme_ms_sms_storeforward.py fails ocassionaly with following error:

  File "/home/jenkins/workspace/osmo-gsm-tester_run-prod/osmo-gsm-tester/suites/smpp/esme_ms_sms_storeforward.py", line 62, in <module>
    wait(ms.sms_was_received, msg)
  File "/home/jenkins/workspace/osmo-gsm-tester_run-prod/osmo-gsm-tester/src/osmo_gsm_tester/testenv.py", line 48, in <lambda>
    wait = lambda *args, **kwargs: event_module.wait(suite_run, *args, **kwargs)
  File "/home/jenkins/workspace/osmo-gsm-tester_run-prod/osmo-gsm-tester/src/osmo_gsm_tester/event_loop.py", line 111, in wait
    raise log.Error('Wait timeout', condition=condition, timeout=timeout, timestep=timestep)
osmo_gsm_tester.log.Error: Wait timeout {condition=<bound method Modem.sms_was_received of /sierra_2>, timeout=300, timestep=1}

Attached run tgz of failing test.

In the pcap file under bsc dir (GSMTAP+RSL), it can be seen that BSC starts paging the BTS, but eventually it expires (T3113) due to no Paging Response from MS. But immediately after (few ms later) the Paging Response arrives, but then it finds no subscriber (probably removed due to T3113 expiration. Then, nothing is communicated towards the MS (not sure what should be sent in that case, but I suspect the MS expects the BSC to do next step).

20181102063651613 DPAG <0005> paging.c:90 (bts=0) Going to send paging commands: imsi: 901700000015252 tmsi: 0x314b6ebe for ch. type 0 (attempt 16)
20181102063651613 DLMI <0017> input/ipaccess.c:356 TX 2: 0c 15 01 90 0e 02 0c 05 f4 31 4b 6e be 28 00
20181102063652114 DPAG <0005> paging.c:90 (bts=0) Going to send paging commands: imsi: 901700000015252 tmsi: 0x314b6ebe for ch. type 0 (attempt 17)
20181102063652114 DLMI <0017> input/ipaccess.c:356 TX 2: 0c 15 01 90 0e 02 0c 05 f4 31 4b 6e be 28 00
20181102063652190 DLMI <0017> input/ipaccess.c:251 RX 2: 0c 12 01 90 0f 00 c7
20181102063652615 DPAG <0005> paging.c:90 (bts=0) Going to send paging commands: imsi: 901700000015252 tmsi: 0x314b6ebe for ch. type 0 (attempt 18)
20181102063652615 DLMI <0017> input/ipaccess.c:356 TX 2: 0c 15 01 90 0e 02 0c 05 f4 31 4b 6e be 28 00
20181102063653097 DPAG <0005> paging.c:281 T3113 expired for request 0x611000000e60 (IMSI:901700000015252)
20181102063653097 DREF <000a> paging.c:75 BSC subscr IMSI:901700000015252 usage decreases to: 0
20181102063653190 DLMI <0017> input/ipaccess.c:251 RX 2: 0c 12 01 90 0f 00 c7
20181102063653652 DLMI <0017> input/ipaccess.c:251 RX 2: 0c 13 01 88 13 8e 5a f7 11 00
20181102063653653 DRSL <0003> abis_rsl.c:1362 (bts=0) CHAN RQD: reason: answer to paging (ra=0x8e, neci=0x01, chreq_reason=0x01)
20181102063653653 DRLL <0000> lchan_select.c:159 (bts=0) lchan_select_by_type(SDCCH)
20181102063653653 DRLL <0000> lchan_select.c:86 looking for lchan CCCH+SDCCH4: (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4,state=UNUSED) ss=0 is available
20181102063653653 DCHAN <0010> lchan_select.c:253 lchan(0-0-0-CCCH_SDCCH4-0)[0x612000007ba0]{UNUSED}: (type=SDCCH) Selected
20181102063653653 DCHAN <0010> abis_rsl.c:1426 lchan(0-0-0-CCCH_SDCCH4-0)[0x612000007ba0]{UNUSED}: (type=SDCCH) MS: Channel Request: reason=PAGING ra=0x8e ta=0
20181102063653653 DCHAN <0010> lchan_fsm.c:318 lchan(0-0-0-CCCH_SDCCH4-0)[0x612000007ba0]{UNUSED}: Received Event LCHAN_EV_ACTIVATE
20181102063653653 DCHAN <0010> lchan_fsm.c:547 lchan(0-0-0-CCCH_SDCCH4-0)[0x612000007ba0]{UNUSED}: state_chg to WAIT_TS_READY
20181102063653653 DCHAN <0010> lchan_fsm.c:573 lchan(0-0-0-CCCH_SDCCH4-0)[0x612000007ba0]{WAIT_TS_READY}: (type=SDCCH) Activation requested: FOR_MS_CHANNEL_REQUEST voice=no MGW-ci=none type=SDCCH tch-mode=SIGNALLING
20181102063653653 DTS <0011> lchan_fsm.c:577 timeslot(0-0-0-CCCH_SDCCH4)[0x612000009220]{UNUSED}: Received Event TS_EV_LCHAN_REQUESTED
20181102063653653 DTS <0011> timeslot_fsm.c:328 timeslot(0-0-0-CCCH_SDCCH4)[0x612000009220]{UNUSED}: state_chg to IN_USE
20181102063653653 DCHAN <0010> timeslot_fsm.c:104 lchan(0-0-0-CCCH_SDCCH4-0)[0x612000007ba0]{WAIT_TS_READY}: Received Event LCHAN_EV_TS_READY
20181102063653653 DCHAN <0010> lchan_fsm.c:591 lchan(0-0-0-CCCH_SDCCH4-0)[0x612000007ba0]{WAIT_TS_READY}: state_chg to WAIT_ACTIV_ACK
20181102063653653 DRSL <0003> abis_rsl.c:476 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4,state=IN_USE) Tx RSL Channel Activate with act_type=INITIAL
20181102063653654 DLMI <0017> input/ipaccess.c:356 TX 2: 08 21 01 20 03 00 06 04 00 03 01 00 05 06 64 20 e3 64 72 00 04 00 0d 1f 18 00
20181102063653661 DLMI <0017> input/ipaccess.c:251 RX 2: 08 22 01 20 08 5b e5
20181102063653662 DCHAN <0010> abis_rsl.c:1129 lchan(0-0-0-CCCH_SDCCH4-0)[0x612000007ba0]{WAIT_ACTIV_ACK}: (type=SDCCH) Rx CHAN_ACTIV_ACK
20181102063653662 DCHAN <0010> abis_rsl.c:1141 lchan(0-0-0-CCCH_SDCCH4-0)[0x612000007ba0]{WAIT_ACTIV_ACK}: Received Event LCHAN_EV_RSL_CHAN_ACTIV_ACK
20181102063653662 DCHAN <0010> lchan_fsm.c:715 lchan(0-0-0-CCCH_SDCCH4-0)[0x612000007ba0]{WAIT_ACTIV_ACK}: (type=SDCCH) Tx RR Immediate Assignment
20181102063653662 DCHAN <0010> lchan_fsm.c:764 lchan(0-0-0-CCCH_SDCCH4-0)[0x612000007ba0]{WAIT_ACTIV_ACK}: state_chg to WAIT_RLL_RTP_ESTABLISH
20181102063653662 DLMI <0017> input/ipaccess.c:356 TX 2: 0c 16 01 90 2b 17 2d 06 3f 03 20 e3 64 8e 5a f7 00 00 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b
20181102063653707 DHODEC <0009> handover_decision_2.c:1847 (BTS 0) No congestion check: Assignment and Handover both disabled
20181102063653708 DHODEC <0009> handover_decision_2.c:162 HO algorithm 2: next periodical congestion check in 10 seconds
20181102063653967 DLMI <0017> input/ipaccess.c:251 RX 2: 02 06 01 20 02 00 0b 00 0d 06 27 07 03 50 58 a6 05 f4 31 4b 6e be
20181102063653967 DCHAN <0010> abis_rsl.c:1614 lchan(0-0-0-CCCH_SDCCH4-0)[0x612000007ba0]{WAIT_RLL_RTP_ESTABLISH}: (type=SDCCH) SAPI=0 ESTABLISH INDICATION
20181102063653967 DCHAN <0010> abis_rsl.c:1647 lchan(0-0-0-CCCH_SDCCH4-0)[0x612000007ba0]{WAIT_RLL_RTP_ESTABLISH}: Received Event LCHAN_EV_RLL_ESTABLISH_IND
20181102063653967 DCHAN <0010> lchan_fsm.c:782 lchan(0-0-0-CCCH_SDCCH4-0)[0x612000007ba0]{WAIT_RLL_RTP_ESTABLISH}: state_chg to ESTABLISHED
20181102063653967 DMSC <0007> fsm.c:299 SUBSCR_CONN[0x612000005aa0]{INIT}: Allocated
20181102063653967 DLCLS <000f> fsm.c:299 LCLS[0x612000005920]{NO_LCLS}: Allocated
20181102063653967 DLCLS <000f> fsm.c:329 LCLS[0x612000005920]{NO_LCLS}: is child of SUBSCR_CONN[0x612000005aa0]
20181102063653967 DMSC <0007> gsm_08_08.c:374 Tx MSC COMPL L3
20181102063653967 DRR <0002> gsm_08_08.c:269 PAGING RESPONSE: MI(TMSI)=827027134
20181102063653968 DMSC <0007> gsm_08_08.c:344 Got paged but no subscriber found.
20181102063653968 DMSC <0007> gsm_08_08.c:379 Failed to find a MSC for a connection.
20181102063654168 DLINP <0015> stream.c:275 connected read

Then, a while later a new (actually probably a retransmission of the same one) Paging CMD arrives from MSC, and then BTS/MS do nothing, probably due to still waiting for some feedback from previous one, and test goes on with BSC sending Paging CMD all he time to the BTS and nothing else happening until test times out and fails.