Actions
Bug #3472
closedGPRS connection is in a state where pdp-context is active, but data TX cannot initiate from Network side.
Start date:
08/18/2018
Due date:
% Done:
0%
Spec Reference:
Description
Very vague analysis here, just wanted to save this (limited but hopefully clear) log in public place.
TODO: Get a full trace of this behaviour.
As the title says, the pdp-context is active, generating traffic from the network side results in:
DTBF <0008> ../../git/src/tbf.cpp:1065 ********** DL-TBF starts here ********** DTBF <0008> ../../git/src/tbf.cpp:1067 Allocating DL TBF: MS_CLASS=0/0 DTBF <0008> ../../git/src/tbf.cpp:537 TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL) Setting Control TS 6 DTBF <0008> ../../git/src/tbf.cpp:922 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=NULL) Allocated: trx = 0, ul_slots = 40, dl_slots = 40 DTBF <0008> ../../git/src/tbf_dl.cpp:510 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=NULL) changes state from NULL to ASSIGN DTBF <0008> ../../git/src/bts.cpp:799 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) TX: START Immediate Assignment Downlink (PCH) DTBF <0008> ../../git/src/bts.cpp:556 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) starting timer T0 [assignment (AGCH)] with 0 sec. 200000 microsec, cur_fn=1779843 DTBF <0008> ../../git/src/tbf.cpp:1133 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) timer 0 expired. cur_fn=1779886 DTBF <0008> ../../git/src/tbf.cpp:514 ********** DL-TBF update ********** DTBF <0008> ../../git/src/tbf_dl.cpp:496 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) changes DL ASS state from GPRS_RLCMAC_DL_ASS_NONE to GPRS_RLCMAC_DL_ASS_SEND_ASS DTBF <0008> ../../git/src/tbf_dl.cpp:500 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) changes state from ASSIGN to ASSIGN DTBF <0008> ../../git/src/tbf_dl.cpp:500 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) set ass. type PACCH [prev CCCH:0, PACCH:0] DTBF <0008> ../../git/src/tbf_dl.cpp:503 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) starting timer T0 [assignment (PACCH)] with 2 sec. 0 microsec, cur_fn=1779886 DTBF <0008> ../../git/src/tbf.cpp:1245 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) New and old TBF are the same. DTBF <0008> ../../git/src/tbf.cpp:1266 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH) DTBF <0008> ../../git/src/tbf.cpp:1273 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ DTBF <0008> ../../git/src/tbf.cpp:1276 ------------------------- TX : Packet Downlink Assignment ------------------------- DTBF <0008> ../../git/src/tbf.cpp:784 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) poll timeout for FN=1779903, TS=6 (curr FN 1779916) DTBF <0008> ../../git/src/tbf.cpp:834 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) Timeout for polling PACKET CONTROL ACK for PACKET DOWNLINK ASSIGNMENT. DTBF <0008> ../../git/src/tbf.cpp:1179 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) Assignment was on PACCH DTBF <0008> ../../git/src/tbf.cpp:1187 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) No downlink ACK received yet DTBF <0008> ../../git/src/tbf.cpp:1245 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) New and old TBF are the same. DTBF <0008> ../../git/src/tbf.cpp:1266 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH) DTBF <0008> ../../git/src/tbf.cpp:1273 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ DTBF <0008> ../../git/src/tbf.cpp:1276 ------------------------- TX : Packet Downlink Assignment ------------------------- DTBF <0008> ../../git/src/tbf.cpp:784 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) poll timeout for FN=1779934, TS=6 (curr FN 1779951) DTBF <0008> ../../git/src/tbf.cpp:1245 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) New and old TBF are the same. DTBF <0008> ../../git/src/tbf.cpp:1266 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH) DTBF <0008> ../../git/src/tbf.cpp:1273 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ DTBF <0008> ../../git/src/tbf.cpp:1276 ------------------------- TX : Packet Downlink Assignment ------------------------- DTBF <0008> ../../git/src/tbf.cpp:784 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) poll timeout for FN=1779968, TS=6 (curr FN 1779986) DTBF <0008> ../../git/src/tbf.cpp:1245 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) New and old TBF are the same. DTBF <0008> ../../git/src/tbf.cpp:1266 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH) DTBF <0008> ../../git/src/tbf.cpp:1273 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ DTBF <0008> ../../git/src/tbf.cpp:1276 ------------------------- TX : Packet Downlink Assignment ------------------------- DTBF <0008> ../../git/src/tbf.cpp:784 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) poll timeout for FN=1780003, TS=6 (curr FN 1780016) DTBF <0008> ../../git/src/tbf.cpp:1245 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) New and old TBF are the same. DTBF <0008> ../../git/src/tbf.cpp:1266 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH) DTBF <0008> ../../git/src/tbf.cpp:1273 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ DTBF <0008> ../../git/src/tbf.cpp:1276 ------------------------- TX : Packet Downlink Assignment ------------------------- DTBF <0008> ../../git/src/tbf.cpp:784 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) poll timeout for FN=1780033, TS=6 (curr FN 1780046) DTBF <0008> ../../git/src/tbf.cpp:1245 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) New and old TBF are the same. DTBF <0008> ../../git/src/tbf.cpp:1266 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH) DTBF <0008> ../../git/src/tbf.cpp:1273 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ DTBF <0008> ../../git/src/tbf.cpp:1276 ------------------------- TX : Packet Downlink Assignment ------------------------- DTBF <0008> ../../git/src/tbf.cpp:784 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) poll timeout for FN=1780064, TS=6 (curr FN 1780077) DTBF <0008> ../../git/src/tbf.cpp:1245 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) New and old TBF are the same. DTBF <0008> ../../git/src/tbf.cpp:1266 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH) DTBF <0008> ../../git/src/tbf.cpp:1273 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ DTBF <0008> ../../git/src/tbf.cpp:1276 ------------------------- TX : Packet Downlink Assignment ------------------------- DTBF <0008> ../../git/src/tbf.cpp:784 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) poll timeout for FN=1780094, TS=6 (curr FN 1780111) DTBF <0008> ../../git/src/tbf.cpp:1245 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) New and old TBF are the same. DTBF <0008> ../../git/src/tbf.cpp:1266 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH) DTBF <0008> ../../git/src/tbf.cpp:1273 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ DTBF <0008> ../../git/src/tbf.cpp:1276 ------------------------- TX : Packet Downlink Assignment ------------------------- DTBF <0008> ../../git/src/tbf.cpp:784 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) poll timeout for FN=1780129, TS=6 (curr FN 1780146) DTBF <0008> ../../git/src/tbf.cpp:597 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) N3105 exceeded MAX (8) DTBF <0008> ../../git/src/tbf.cpp:842 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) changes state from ASSIGN to RELEASING DTBF <0008> ../../git/src/tbf.cpp:843 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=RELEASING) starting timer T3195 [MAX N3105 reached] with 5 sec. 0 microsec, cur_fn=1780146 DTBF <0008> ../../git/src/tbf.cpp:1133 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=RELEASING) timer 0 expired. cur_fn=1780319 DTBF <0008> ../../git/src/tbf.cpp:1142 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=RELEASING) Error: TBF is not in assign state DTBF <0008> ../../git/src/tbf.cpp:646 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=RELEASING) T3195 timeout expired, freeing TBF DTBF <0008> ../../git/src/tbf.cpp:1179 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=RELEASING) Assignment was on PACCH DTBF <0008> ../../git/src/tbf.cpp:1187 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=RELEASING) No downlink ACK received yet DTBF <0008> ../../git/src/tbf_dl.cpp:1138 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=RELEASING) changes state from RELEASING to RELEASING DTBF <0008> ../../git/src/tbf.cpp:481 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=RELEASING) free DTBF <0008> ../../git/src/tbf.cpp:494 ********** DL-TBF ends here **********
This repeats for as long as the network side has traffic..
Initiating traffic from the phone side then results in:
DL1IF <0001> ../../git/src/pcu_l1_if.cpp:389 RACH request received: sapi=1 qta=0, ra=122, fn=1786070, cur_fn=1786074, is_11bit=0 DTBF <0008> ../../git/src/tbf.cpp:974 ********** UL-TBF starts here ********** DTBF <0008> ../../git/src/tbf.cpp:976 Allocating UL TBF: MS_CLASS=0/0 DTBF <0008> ../../git/src/tbf.cpp:537 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL) Setting Control TS 6 DTBF <0008> ../../git/src/tbf.cpp:922 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL) Allocated: trx = 0, ul_slots = 40, dl_slots = 00 DTBF <0008> ../../git/src/bts.cpp:745 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL) changes state from NULL to FLOW DTBF <0008> ../../git/src/bts.cpp:746 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) set ass. type CCCH [prev CCCH:0, PACCH:0] DTBF <0008> ../../git/src/bts.cpp:747 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) starting timer T3169 [RACH (new UL-TBF)] with 5 sec. 0 microsec, cur_fn=1786074 DTBF <0008> ../../git/src/bts.cpp:748 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) [UPLINK] START DTBF <0008> ../../git/src/bts.cpp:753 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) RX: [PCU <- BTS] RACH qbit-ta=0 ra=0x7a, Fn=1786070 (2,50,0) DTBF <0008> ../../git/src/bts.cpp:754 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) TX: START Immediate Assignment Uplink (AGCH) DTBF <0008> ../../git/src/tbf_ul.cpp:200 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=FLOW) restarting timer T3169 [acked (data)] with 5 sec. 0 microsec, cur_fn=1786104 DTBF <0008> ../../git/src/tbf_ul.cpp:375 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FLOW) changes UL ACK state from GPRS_RLCMAC_UL_ACK_NONE to GPRS_RLCMAC_UL_ACK_SEND_ACK DTBF <0008> ../../git/src/tbf_ul.cpp:169 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FLOW) changes UL ACK state from GPRS_RLCMAC_UL_ACK_SEND_ACK to GPRS_RLCMAC_UL_ACK_NONE DTBF <0008> ../../git/src/tbf_ul.cpp:200 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FLOW) restarting timer T3169 [acked (data)] with 5 sec. 0 microsec, cur_fn=1786109 DTBF <0008> ../../git/src/tbf_ul.cpp:375 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FLOW) changes UL ACK state from GPRS_RLCMAC_UL_ACK_NONE to GPRS_RLCMAC_UL_ACK_SEND_ACK DTBF <0008> ../../git/src/tbf_ul.cpp:169 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FLOW) changes UL ACK state from GPRS_RLCMAC_UL_ACK_SEND_ACK to GPRS_RLCMAC_UL_ACK_NONE DTBF <0008> ../../git/src/tbf_ul.cpp:200 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FLOW) restarting timer T3169 [acked (data)] with 5 sec. 0 microsec, cur_fn=1786113 DTBF <0008> ../../git/src/tbf_ul.cpp:334 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FLOW) changes state from FLOW to FINISHED DTBF <0008> ../../git/src/tbf_ul.cpp:375 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) changes UL ACK state from GPRS_RLCMAC_UL_ACK_NONE to GPRS_RLCMAC_UL_ACK_SEND_ACK DTBF <0008> ../../git/src/tbf.cpp:1065 ********** DL-TBF starts here ********** DTBF <0008> ../../git/src/tbf.cpp:1067 Allocating DL TBF: MS_CLASS=0/0 DTBF <0008> ../../git/src/tbf.cpp:537 TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL) Setting Control TS 6 DTBF <0008> ../../git/src/tbf.cpp:922 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=NULL) Allocated: trx = 0, ul_slots = 40, dl_slots = e0 DTBF <0008> ../../git/src/tbf_dl.cpp:496 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) changes DL ASS state from GPRS_RLCMAC_DL_ASS_NONE to GPRS_RLCMAC_DL_ASS_SEND_ASS DTBF <0008> ../../git/src/tbf_dl.cpp:500 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=NULL) changes state from NULL to ASSIGN DTBF <0008> ../../git/src/tbf_dl.cpp:500 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) set ass. type PACCH [prev CCCH:0, PACCH:0] DTBF <0008> ../../git/src/tbf_dl.cpp:503 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) starting timer T0 [assignment (PACCH)] with 2 sec. 0 microsec, cur_fn=1786113 DTBF <0008> ../../git/src/tbf.cpp:1266 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH) DTBF <0008> ../../git/src/tbf.cpp:1273 +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ DTBF <0008> ../../git/src/tbf.cpp:1276 ------------------------- TX : Packet Downlink Assignment ------------------------- DTBF <0008> ../../git/src/tbf_ul.cpp:200 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) restarting timer T3169 [acked (data)] with 5 sec. 0 microsec, cur_fn=1786117 DTBF <0008> ../../git/src/tbf.cpp:717 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) Polling is already scheduled DTBF <0008> ../../git/src/tbf_ul.cpp:200 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) restarting timer T3169 [acked (data)] with 5 sec. 0 microsec, cur_fn=1786122 DTBF <0008> ../../git/src/tbf.cpp:717 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) Polling is already scheduled DTBF <0008> ../../git/src/tbf_ul.cpp:200 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) restarting timer T3169 [acked (data)] with 5 sec. 0 microsec, cur_fn=1786126 DTBF <0008> ../../git/src/tbf.cpp:717 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) Polling is already scheduled DTBF <0008> ../../git/src/tbf.cpp:717 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) Polling is already scheduled DTBF <0008> ../../git/src/tbf.cpp:717 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) Polling is already scheduled DL1IF <0001> ../../git/src/bts.cpp:848 PH-DATA-IND is updating TLLI=0xf6dafa25: TA 0 -> 0 on TRX = 0, TS = 6, FN = 1786130 DTBF <0008> ../../git/src/pdch.cpp:297 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) RX: [PCU <- BTS] Packet Control Ack DTBF <0008> ../../git/src/pdch.cpp:298 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) changes poll state from GPRS_RLCMAC_POLL_SCHED to GPRS_RLCMAC_POLL_NONE DTBF <0008> ../../git/src/pdch.cpp:311 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) [UPLINK] DOWNLINK ASSIGNED DTBF <0008> ../../git/src/pdch.cpp:314 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) changes DL ASS state from GPRS_RLCMAC_DL_ASS_WAIT_ACK to GPRS_RLCMAC_DL_ASS_NONE DTBF <0008> ../../git/src/pdch.cpp:333 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=ASSIGN) changes state from ASSIGN to FLOW DTBF <0008> ../../git/src/tbf.cpp:614 TBF(TFI=0 TLLI=0xf6dafa25 DIR=DL STATE=FLOW) stopping timer T0 [control acked (DL-TBF)] DL1IF <0001> ../../git/src/bts.cpp:848 PH-DATA-IND is updating TLLI=0xf6dafa25: TA 0 -> 0 on TRX = 0, TS = 6, FN = 1786156 DTBF <0008> ../../git/src/pdch.cpp:297 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) RX: [PCU <- BTS] Packet Control Ack DTBF <0008> ../../git/src/pdch.cpp:298 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) changes poll state from GPRS_RLCMAC_POLL_SCHED to GPRS_RLCMAC_POLL_NONE DTBF <0008> ../../git/src/tbf_ul.cpp:119 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) changes UL ACK state from GPRS_RLCMAC_UL_ACK_WAIT_ACK to GPRS_RLCMAC_UL_ACK_NONE DTBF <0008> ../../git/src/pdch.cpp:303 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) [UPLINK] END DRLCMACMEAS <0007> ../../git/src/gprs_rlcmac_meas.cpp:104 UL RSSI of TLLI=0xf6dafa25: -41 dBm DTBF <0008> ../../git/src/tbf.cpp:481 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) free DTBF <0008> ../../git/src/tbf.cpp:614 TBF(TFI=0 TLLI=0xf6dafa25 DIR=UL STATE=FINISHED) stopping timer T3169 [freeing TBF] DTBF <0008> ../../git/src/tbf.cpp:494 ********** UL-TBF ends here **********
Related issues
Actions