Bug #1931
Updated by dexter about 7 years ago
In some cases, primarily when a the MS requests to deactivate the PDP context a problem allocating a downlink TBF occurs: The observation of the diag interface of the MS shows that that the MS is sending a PDP context deactivation request. The request reaches SGSN and the SGSN responds correctly with a PDP context deactivation ACK. The diag interface on the modem shows that the PDP context deactivation ACK is never received. The MS repeats the request 4 times until it finally gives up. <pre> Thu Jan 19 11:27:19 2017 <0011> gprs_bssgp.c:379 BSSGP TLLI=0xd4d4ca34 Rx UPLINK-UNITDATA Thu Jan 19 11:27:19 2017 <0012> gprs_llc_parse.c:82 LLC SAPI=1 C U GEA0 IOV-UI=0x000000 FCS=0x20b16a CMD=UI DATA Thu Jan 19 11:27:19 2017 <0002> gprs_gmm.c:2444 MM(001010000000001/d4d4ca34) -> DEACTIVATE PDP CONTEXT REQ (cause: Regular deactivation) Thu Jan 19 11:27:19 2017 <000f> sgsn_libgtp.c:286 PDP(001010000000001/0) Delete PDP Context Thu Jan 19 11:27:19 2017 <000f> sgsn_libgtp.c:613 PDP Context was deleted Thu Jan 19 11:27:19 2017 <000f> sgsn_libgtp.c:590 libgtp cb_conf(type=20, cause=128, pdp=(nil), cbp=0x1a2e010) Thu Jan 19 11:27:19 2017 <000f> sgsn_libgtp.c:513 PDP(001010000000001/0) Received DELETE PDP CTX CONF, cause=128(Request accepted) Thu Jan 19 11:27:19 2017 <0013> gprs_sndcp.c:509 SNSM-DEACTIVATE.ind (lle=0x1a2be20, TLLI=d4d4ca34, SAPI=3, NSAPI=5) Thu Jan 19 11:27:19 2017 <0002> gprs_gmm.c:2127 MM(001010000000001/d4d4ca34) <- DEACTIVATE PDP CONTEXT ACK Thu Jan 19 11:27:24 2017 <0011> gprs_bssgp.c:797 BSSGP BVCI=23 Rx Flow Control BVC Thu Jan 19 11:27:27 2017 <0011> gprs_bssgp.c:379 BSSGP TLLI=0xd4d4ca34 Rx UPLINK-UNITDATA Thu Jan 19 11:27:27 2017 <0012> gprs_llc_parse.c:82 LLC SAPI=1 C U GEA0 IOV-UI=0x000000 FCS=0xac2522 CMD=UI DATA Thu Jan 19 11:27:27 2017 <0002> gprs_gmm.c:2444 MM(001010000000001/d4d4ca34) -> DEACTIVATE PDP CONTEXT REQ (cause: Regular deactivation) Thu Jan 19 11:27:27 2017 <0002> gprs_gmm.c:2451 MM(001010000000001/d4d4ca34) Deactivate PDP Context Request for non-existing PDP Context (IMSI=001010000000001, TI=0) Thu Jan 19 11:27:27 2017 <0002> gprs_gmm.c:2127 MM(001010000000001/d4d4ca34) <- DEACTIVATE PDP CONTEXT ACK Thu Jan 19 11:27:30 2017 <000f> gprs_sgsn.c:870 Checking for inactive LLMEs, time = 126147 Thu Jan 19 11:27:34 2017 <0010> gprs_ns.c:528 NSEI=23 Tx NS ALIVE_ACK (NSVCI=23) Thu Jan 19 11:27:34 2017 <0011> gprs_bssgp.c:797 BSSGP BVCI=23 Rx Flow Control BVC Thu Jan 19 11:27:34 2017 <0010> gprs_ns.c:582 NSEI=23 Timer expired in mode tns-test (30 seconds) Thu Jan 19 11:27:34 2017 <0010> gprs_ns.c:515 NSEI=23 Tx NS ALIVE (NSVCI=23) Thu Jan 19 11:27:34 2017 <0010> gprs_ns.c:554 NSEI=23 Starting timer in mode tns-alive (3 seconds) Thu Jan 19 11:27:34 2017 <0010> gprs_ns.c:554 NSEI=23 Starting timer in mode tns-test (30 seconds) Thu Jan 19 11:27:35 2017 <0011> gprs_bssgp.c:379 BSSGP TLLI=0xd4d4ca34 Rx UPLINK-UNITDATA Thu Jan 19 11:27:35 2017 <0012> gprs_llc_parse.c:82 LLC SAPI=1 C U GEA0 IOV-UI=0x000000 FCS=0xb55300 CMD=UI DATA Thu Jan 19 11:27:35 2017 <0002> gprs_gmm.c:2444 MM(001010000000001/d4d4ca34) -> DEACTIVATE PDP CONTEXT REQ (cause: Regular deactivation) Thu Jan 19 11:27:35 2017 <0002> gprs_gmm.c:2451 MM(001010000000001/d4d4ca34) Deactivate PDP Context Request for non-existing PDP Context (IMSI=001010000000001, TI=0) Thu Jan 19 11:27:35 2017 <0002> gprs_gmm.c:2127 MM(001010000000001/d4d4ca34) <- DEACTIVATE PDP CONTEXT ACK Thu Jan 19 11:27:43 2017 <0011> gprs_bssgp.c:379 BSSGP TLLI=0xd4d4ca34 Rx UPLINK-UNITDATA Thu Jan 19 11:27:43 2017 <0012> gprs_llc_parse.c:82 LLC SAPI=1 C U GEA0 IOV-UI=0x000000 FCS=0x39c748 CMD=UI DATA Thu Jan 19 11:27:43 2017 <0002> gprs_gmm.c:2444 MM(001010000000001/d4d4ca34) -> DEACTIVATE PDP CONTEXT REQ (cause: Regular deactivation) Thu Jan 19 11:27:43 2017 <0002> gprs_gmm.c:2451 MM(001010000000001/d4d4ca34) Deactivate PDP Context Request for non-existing PDP Context (IMSI=001010000000001, TI=0) Thu Jan 19 11:27:43 2017 <0002> gprs_gmm.c:2127 MM(001010000000001/d4d4ca34) <- DEACTIVATE PDP CONTEXT ACK Thu Jan 19 11:27:44 2017 <0011> gprs_bssgp.c:797 BSSGP BVCI=23 Rx Flow Control BVC Thu Jan 19 11:27:51 2017 <0011> gprs_bssgp.c:379 BSSGP TLLI=0xd4d4ca34 Rx UPLINK-UNITDATA Thu Jan 19 11:27:51 2017 <0012> gprs_llc_parse.c:82 LLC SAPI=1 C U GEA0 IOV-UI=0x000000 FCS=0xf7702b CMD=UI DATA Thu Jan 19 11:27:51 2017 <0002> gprs_gmm.c:2444 MM(001010000000001/d4d4ca34) -> DEACTIVATE PDP CONTEXT REQ (cause: Regular deactivation) Thu Jan 19 11:27:51 2017 <0002> gprs_gmm.c:2451 MM(001010000000001/d4d4ca34) Deactivate PDP Context Request for non-existing PDP Context (IMSI=001010000000001, TI=0) Thu Jan 19 11:27:51 2017 <0002> gprs_gmm.c:2127 MM(001010000000001/d4d4ca34) <- DEACTIVATE PDP CONTEXT ACK Thu Jan 19 11:27:54 2017 <0011> gprs_bssgp.c:797 BSSGP BVCI=23 Rx Flow Control BVC Thu Jan 19 11:28:00 2017 <000f> gprs_sgsn.c:870 Checking for inactive LLMEs, time = 126177 Thu Jan 19 11:28:04 2017 <0010> gprs_ns.c:528 NSEI=23 Tx NS ALIVE_ACK (NSVCI=23) Thu Jan 19 11:28:04 2017 <0011> gprs_bssgp.c:797 BSSGP BVCI=23 Rx Flow Control BVC Thu Jan 19 11:28:04 2017 <0010> gprs_ns.c:582 NSEI=23 Timer expired in mode tns-test (30 seconds) </pre> <pre> By the diag log we see that the downlink assignment message, the PCU is sending is missing, while the log of the PCU confirms that the downlink assignment message is sent: <pre> Thu Jan 19 11:27:51 2017 <0001> pcu_l1_if.cpp:350 RACH request received: sapi=1 qta=0, ra=123, fn=82125 Thu Jan 19 11:27:51 2017 <0002> bts.cpp:562 MS requests UL TBF on RACH, so we provide one ra=0x7b Fn=82125 qta=0 is_11bit=0: Thu Jan 19 11:27:51 2017 <0002> bts.cpp:708 pcu has not received burst type from bts Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:694 ********** TBF starts here ********** Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:696 Allocating UL TBF: MS_CLASS=0/0 Thu Jan 19 11:27:51 2017 <0002> gprs_ms.cpp:115 Creating MS object, TLLI = 0x00000000 Thu Jan 19 11:27:51 2017 <0002> bts.cpp:454 Searching for first unallocated TFI: TRX=0 Thu Jan 19 11:27:51 2017 <0002> bts.cpp:464 Found TFI=0. Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:525 Slot Allocation (Algorithm B) for unknown class (assuming 12) Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:560 - Rx=4 Tx=4 Sum Rx+Tx=5 Tta=2 Ttb=1 Tra=2 Trb=1 Type=1 Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:157 - Skipping TS 0, because not enabled Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:157 - Skipping TS 1, because not enabled Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:157 - Skipping TS 2, because not enabled Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:157 - Skipping TS 3, because not enabled Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:157 - Skipping TS 4, because not enabled Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:157 - Skipping TS 5, because not enabled Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:157 - Skipping TS 6, because not enabled Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:579 - Possible DL/UL slots: (TS=0)".......C"(TS=7) Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:940 - Selected UL slots: (TS=0)".......U"(TS=7), single Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:966 Using single slot at TS 7 for UL Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:990 - Reserved DL/UL slots: (TS=0)".......C"(TS=7) Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:1017 - Assigning UL TS 7 Thu Jan 19 11:27:51 2017 <0002> bts.cpp:1681 PDCH(TS 7, TRX 0): Attaching TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL), 1 TBFs, USFs = 01, TFIs = 00000001. Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:399 - Setting Control TS 7 Thu Jan 19 11:27:51 2017 <0002> gprs_ms.cpp:268 Attaching TBF to MS object, TLLI = 0x00000000, TBF = TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL) Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:647 Allocated TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL): trx = 0, ul_slots = 80, dl_slots = 00 Thu Jan 19 11:27:51 2017 <0002> gprs_ms.cpp:471 Modifying MS object, TLLI = 0x00000000, TA 220 -> 0 Thu Jan 19 11:27:51 2017 <0002> bts.cpp:294 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL) changes state from NULL to FLOW Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:422 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) starting timer 3169. Thu Jan 19 11:27:51 2017 <0002> bts.cpp:611 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) [UPLINK] START Thu Jan 19 11:27:51 2017 <0002> bts.cpp:617 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) RX: [PCU <- BTS] RACH qbit-ta=0 ra=0x7b, Fn=82125 (29,15,17) Thu Jan 19 11:27:51 2017 <0002> bts.cpp:620 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) TX: START Immediate Assignment Uplink (AGCH) Thu Jan 19 11:27:51 2017 <0002> bts.cpp:640 - TRX=0 (866) TS=7 TA=0 TSC=7 TFI=0 USF=0 Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:109 Received RTS for PDCH: TRX=0 TS=7 FN=82134 block_nr=6 scheduling USF=0 for required uplink resource of UL TFI=0 Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:109 Received RTS for PDCH: TRX=0 TS=7 FN=82138 block_nr=7 scheduling USF=0 for required uplink resource of UL TFI=0 Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:109 Received RTS for PDCH: TRX=0 TS=7 FN=82142 block_nr=8 scheduling USF=0 for required uplink resource of UL TFI=0 Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:109 Received RTS for PDCH: TRX=0 TS=7 FN=82147 block_nr=9 scheduling USF=0 for required uplink resource of UL TFI=0 Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:109 Received RTS for PDCH: TRX=0 TS=7 FN=82151 block_nr=10 scheduling USF=0 for required uplink resource of UL TFI=0 Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:109 Received RTS for PDCH: TRX=0 TS=7 FN=82155 block_nr=11 scheduling USF=0 for required uplink resource of UL TFI=0 Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:109 Received RTS for PDCH: TRX=0 TS=7 FN=82160 block_nr=0 scheduling USF=0 for required uplink resource of UL TFI=0 Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:109 Received RTS for PDCH: TRX=0 TS=7 FN=82164 block_nr=1 scheduling USF=0 for required uplink resource of UL TFI=0 Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:109 Received RTS for PDCH: TRX=0 TS=7 FN=82168 block_nr=2 scheduling USF=0 for required uplink resource of UL TFI=0 Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:109 Received RTS for PDCH: TRX=0 TS=7 FN=82173 block_nr=3 scheduling USF=0 for required uplink resource of UL TFI=0 Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:109 Received RTS for PDCH: TRX=0 TS=7 FN=82177 block_nr=4 scheduling USF=0 for required uplink resource of UL TFI=0 Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:109 Received RTS for PDCH: TRX=0 TS=7 FN=82181 block_nr=5 scheduling USF=0 for required uplink resource of UL TFI=0 Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:109 Received RTS for PDCH: TRX=0 TS=7 FN=82186 block_nr=6 scheduling USF=0 for required uplink resource of UL TFI=0 Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:426 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) restarting timer 3169 while old timer 3169 pending Thu Jan 19 11:27:51 2017 <0002> gprs_ms.cpp:457 Modifying MS object, TLLI = 0x00000000, IMSI '' -> '001010000000001' Thu Jan 19 11:27:51 2017 <0002> gprs_ms.cpp:361 Clearing MS object, TLLI: 0xd4d4ca34, IMSI: '001010000000001' Thu Jan 19 11:27:51 2017 <0002> gprs_ms.cpp:396 Modifying MS object, UL TLLI: 0x00000000 -> 0xd4d4ca34, not yet confirmed Thu Jan 19 11:27:51 2017 <0002> gprs_ms.cpp:141 Destroying MS object, TLLI = 0x00000000 Thu Jan 19 11:27:51 2017 <0009> tbf_ul.cpp:373 LLC [PCU -> SGSN] TBF(TFI=0 TLLI=0xd4d4ca34 DIR=UL STATE=FLOW) len=10 Thu Jan 19 11:27:51 2017 <0002> tbf_ul.cpp:294 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=UL STATE=FLOW) changes state from FLOW to FINISHED Thu Jan 19 11:27:51 2017 <0009> gprs_bssgp_pcu.cpp:180 LLC [SGSN -> PCU] = TLLI: 0xd4d4ca34 IMSI: 001010000000001 len: 8 Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:775 ********** TBF starts here ********** Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:777 Allocating DL TBF: MS_CLASS=0/0 Thu Jan 19 11:27:51 2017 <0002> bts.cpp:454 Searching for first unallocated TFI: TRX=0 Thu Jan 19 11:27:51 2017 <0002> bts.cpp:464 Found TFI=0. Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:902 - Selected DL slots: (TS=0)".......D"(TS=7), single Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:966 Using single slot at TS 7 for DL Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac_ts_alloc.cpp:1004 - Assigning DL TS 7 Thu Jan 19 11:27:51 2017 <0002> bts.cpp:1681 PDCH(TS 7, TRX 0): Attaching TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL), 1 TBFs, USFs = 01, TFIs = 00000001. Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:399 - Setting Control TS 7 Thu Jan 19 11:27:51 2017 <0002> gprs_ms.cpp:287 Attaching TBF to MS object, TLLI = 0xd4d4ca34, TBF = TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=NULL) Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:647 Allocated TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=NULL): trx = 0, ul_slots = 80, dl_slots = 80 Thu Jan 19 11:27:51 2017 <0002> gprs_ms.cpp:430 Modifying MS object, TLLI: 0xd4d4ca34 confirmed Thu Jan 19 11:27:51 2017 <0002> tbf_dl.cpp:161 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=NULL) [DOWNLINK] START Thu Jan 19 11:27:51 2017 <0002> bts.cpp:749 Send dowlink assignment for TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=NULL) on PCH, no TBF exist (IMSI=001010000000001) Thu Jan 19 11:27:51 2017 <0002> bts.cpp:294 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=NULL) changes state from NULL to ASSIGN Thu Jan 19 11:27:51 2017 <0002> gprs_rlcmac.cpp:35 TX: [PCU -> BTS] Paging Request (CCCH) Thu Jan 19 11:27:51 2017 <0002> bts.cpp:770 TX: START TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) Immediate Assignment Downlink (PCH) Thu Jan 19 11:27:51 2017 <0002> bts.cpp:777 - TRX=0 (866) TS=7 TA=0 pollFN=-1 Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:422 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) starting timer 0. Thu Jan 19 11:27:51 2017 <0002> tbf_dl.cpp:90 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) append Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:487 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=UL STATE=FINISHED): Scheduling polling at FN 82203 TS 7 Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:181 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xd4d4ca34 DIR=UL STATE=FINISHED) (TRX=0, TS=7) Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:426 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=UL STATE=FINISHED) restarting timer 3169 while old timer 3169 pending Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:426 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=UL STATE=FINISHED) restarting timer 3169 while old timer 3169 pending Thu Jan 19 11:27:51 2017 <0006> gprs_rlcmac_sched.cpp:329 Received RTS for PDCH: TRX=0 TS=7 FN=82199 block_nr=9 scheduling free USF for polling at FN=82203 of TBF(TFI=0 TLLI=0xd4d4ca34 DIR=UL STATE=FINISHED) Thu Jan 19 11:27:51 2017 <0002> bts.cpp:1448 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ Thu Jan 19 11:27:51 2017 <0002> bts.cpp:1451 ------------------------- RX : Uplink Control Block ------------------------- Thu Jan 19 11:27:51 2017 <0002> bts.cpp:955 RX: [PCU <- BTS] TBF(TFI=0 TLLI=0xd4d4ca34 DIR=UL STATE=FINISHED) Packet Control Ack Thu Jan 19 11:27:51 2017 <0002> bts.cpp:960 TBF: [UPLINK] END TBF(TFI=0 TLLI=0xd4d4ca34 DIR=UL STATE=FINISHED) Thu Jan 19 11:27:51 2017 <0007> gprs_rlcmac_meas.cpp:104 UL RSSI of TLLI=0xd4d4ca34: -103 dBm Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:342 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=UL STATE=FINISHED) free Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:447 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=UL STATE=FINISHED) stopping timer 3169. Thu Jan 19 11:27:51 2017 <0002> bts.cpp:1701 PDCH(TS 7, TRX 0): Detaching TBF(TFI=0 TLLI=0xd4d4ca34 DIR=UL STATE=FINISHED), 0 TBFs, USFs = 00, TFIs = 00000000. Thu Jan 19 11:27:51 2017 <0002> gprs_ms.cpp:324 Detaching TBF from MS object, TLLI = 0xd4d4ca34, TBF = TBF(TFI=0 TLLI=0xd4d4ca34 DIR=UL STATE=FINISHED) Thu Jan 19 11:27:51 2017 <0002> tbf.cpp:363 ********** TBF ends here ********** Thu Jan 19 11:27:53 2017 <0002> tbf.cpp:829 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) timer 0 expired. Thu Jan 19 11:27:53 2017 <0002> tbf.cpp:372 ********** TBF update ********** Thu Jan 19 11:27:53 2017 <0002> bts.cpp:1701 PDCH(TS 7, TRX 0): Detaching TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN), 0 TBFs, USFs = 00, TFIs = 00000000. Thu Jan 19 11:27:53 2017 <0002> bts.cpp:454 Searching for first unallocated TFI: TRX=0 Thu Jan 19 11:27:53 2017 <0002> bts.cpp:464 Found TFI=0. Thu Jan 19 11:27:53 2017 <0002> gprs_rlcmac_ts_alloc.cpp:902 - Selected DL slots: (TS=0)".......D"(TS=7) Thu Jan 19 11:27:53 2017 <0002> gprs_rlcmac_ts_alloc.cpp:970 Using 1 slots for DL Thu Jan 19 11:27:53 2017 <0002> gprs_rlcmac_ts_alloc.cpp:1004 - Assigning DL TS 7 Thu Jan 19 11:27:53 2017 <0002> bts.cpp:1681 PDCH(TS 7, TRX 0): Attaching TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN), 1 TBFs, USFs = 00, TFIs = 00000001. Thu Jan 19 11:27:53 2017 <0002> bts.cpp:736 Send dowlink assignment on PACCH, because TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) exists Thu Jan 19 11:27:53 2017 <0002> bts.cpp:294 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) changes state from ASSIGN to ASSIGN Thu Jan 19 11:27:53 2017 <0002> tbf.cpp:422 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) starting timer 0. Thu Jan 19 11:27:53 2017 <0002> tbf.cpp:985 New and old TBF are the same TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) Thu Jan 19 11:27:53 2017 <0002> tbf.cpp:1007 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH) Thu Jan 19 11:27:53 2017 <0002> tbf.cpp:1014 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ Thu Jan 19 11:27:53 2017 <0002> tbf.cpp:1017 ------------------------- TX : Packet Downlink Assignment ------------------------- Thu Jan 19 11:27:53 2017 <0002> tbf.cpp:487 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN): Scheduling polling at FN 82636 TS 7 Thu Jan 19 11:27:53 2017 <0006> gprs_rlcmac_sched.cpp:181 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) (TRX=0, TS=7) Thu Jan 19 11:27:53 2017 <0006> gprs_rlcmac_sched.cpp:329 Received RTS for PDCH: TRX=0 TS=7 FN=82632 block_nr=1 scheduling free USF for polling at FN=82636 of TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:498 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) poll timeout for FN=82636, TS=7 (curr FN 82697) Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:553 - Timeout for polling PACKET CONTROL ACK for PACKET DOWNLINK ASSIGNMENT. Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:914 - Assignment was on PACCH Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:922 - No downlink ACK received yet Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:985 New and old TBF are the same TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:1007 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH) Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:1014 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:1017 ------------------------- TX : Packet Downlink Assignment ------------------------- Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:487 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN): Scheduling polling at FN 82710 TS 7 Thu Jan 19 11:27:54 2017 <0006> gprs_rlcmac_sched.cpp:181 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) (TRX=0, TS=7) Thu Jan 19 11:27:54 2017 <0006> gprs_rlcmac_sched.cpp:329 Received RTS for PDCH: TRX=0 TS=7 FN=82706 block_nr=6 scheduling free USF for polling at FN=82710 of TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:498 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) poll timeout for FN=82710, TS=7 (curr FN 82771) Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:985 New and old TBF are the same TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:1007 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH) Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:1014 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:1017 ------------------------- TX : Packet Downlink Assignment ------------------------- Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:487 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN): Scheduling polling at FN 82784 TS 7 Thu Jan 19 11:27:54 2017 <0006> gprs_rlcmac_sched.cpp:181 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) (TRX=0, TS=7) Thu Jan 19 11:27:54 2017 <0006> gprs_rlcmac_sched.cpp:329 Received RTS for PDCH: TRX=0 TS=7 FN=82779 block_nr=11 scheduling free USF for polling at FN=82784 of TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:498 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) poll timeout for FN=82784, TS=7 (curr FN 82849) Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:985 New and old TBF are the same TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:1007 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH) Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:1014 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:1017 ------------------------- TX : Packet Downlink Assignment ------------------------- Thu Jan 19 11:27:54 2017 <0002> tbf.cpp:487 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN): Scheduling polling at FN 82862 TS 7 Thu Jan 19 11:27:54 2017 <0006> gprs_rlcmac_sched.cpp:181 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) (TRX=0, TS=7) Thu Jan 19 11:27:54 2017 <0006> gprs_rlcmac_sched.cpp:329 Received RTS for PDCH: TRX=0 TS=7 FN=82857 block_nr=5 scheduling free USF for polling at FN=82862 of TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:498 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) poll timeout for FN=82862, TS=7 (curr FN 82927) Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:985 New and old TBF are the same TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:1007 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH) Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:1014 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:1017 ------------------------- TX : Packet Downlink Assignment ------------------------- Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:487 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN): Scheduling polling at FN 82940 TS 7 Thu Jan 19 11:27:55 2017 <0006> gprs_rlcmac_sched.cpp:181 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) (TRX=0, TS=7) Thu Jan 19 11:27:55 2017 <0006> gprs_rlcmac_sched.cpp:329 Received RTS for PDCH: TRX=0 TS=7 FN=82935 block_nr=11 scheduling free USF for polling at FN=82940 of TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:498 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) poll timeout for FN=82940, TS=7 (curr FN 83005) Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:985 New and old TBF are the same TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:1007 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH) Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:1014 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:1017 ------------------------- TX : Packet Downlink Assignment ------------------------- Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:487 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN): Scheduling polling at FN 83018 TS 7 Thu Jan 19 11:27:55 2017 <0006> gprs_rlcmac_sched.cpp:181 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) (TRX=0, TS=7) Thu Jan 19 11:27:55 2017 <0006> gprs_rlcmac_sched.cpp:329 Received RTS for PDCH: TRX=0 TS=7 FN=83013 block_nr=5 scheduling free USF for polling at FN=83018 of TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:829 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) timer 0 expired. Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:838 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) releasing due to PACCH assignment timeout. Thu Jan 19 11:27:55 2017 <0002> tbf_dl.cpp:294 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=ASSIGN) changes state from ASSIGN to RELEASING Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:342 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=RELEASING) free Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:354 TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=RELEASING) Software error: Pending downlink assignment. This may not happen, because the assignment message never gets transmitted. Please be sure not to free in this state. PLEASE FIX! Thu Jan 19 11:27:55 2017 <0002> bts.cpp:1701 PDCH(TS 7, TRX 0): Detaching TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=RELEASING), 0 TBFs, USFs = 00, TFIs = 00000000. Thu Jan 19 11:27:55 2017 <0002> gprs_ms.cpp:324 Detaching TBF from MS object, TLLI = 0xd4d4ca34, TBF = TBF(TFI=0 TLLI=0xd4d4ca34 DIR=DL STATE=RELEASING) Thu Jan 19 11:27:55 2017 <0002> tbf.cpp:363 ********** TBF ends here ********** </pre> With some experimentation we found out that after changing "gprs mode gprs" to "gprs mode egprs" in nitb.cfg the problem seems to dissappear, this leads to the assumption that it is a timing problem between osmo-bts and osmo-pcu. The problem has been observerd with an OCTBTS/Octphy, see also traces, logs and configuration files in the attachment.
