Project

General

Profile

Actions

Bug #5472

closed

osmo-pcu: {SEND_ASS}: Event SCHED_ASS not permitted

Added by pespin about 2 years ago. Updated 9 months ago.

Status:
Resolved
Priority:
Normal
Assignee:
Target version:
-
Start date:
03/01/2022
Due date:
% Done:

100%

Spec Reference:

Description

Mar  1 20:20:03 OsmoPCU: DTBF NOTICE tbf_ul_ass_fsm.c:241 TBF(TFI=0 TLLI=0xe5751051 DIR=UL STATE=ASSIGN EGPRS) Timeout for polling PACKET CONTROL ACK for PACKET UPLINK ASSIGNMENT: |Assignment was on PACCH|
Uplink data was received|
Mar  1 20:20:03 OsmoPCU: DTBF INFO tbf_ul_ass_fsm.c:244 UL_ASS_TBF(UL-TFI_0)[0x7cd840]{WAIT_ACK}: state_chg to SEND_ASS
Mar  1 20:20:03 OsmoPCU: DLBSSGP INFO gprs_bssgp_pcu.c:181 LLC [SGSN -> PCU] = TLLI: 0xe5751051 IMSI: <ERASED_A> len: 62
Mar  1 20:20:03 OsmoPCU: DTBF INFO tbf_dl.cpp:133 MS(TLLI=0xe5751051, IMSI=<ERASED_A>, TA=0, 12/12, UL) Allocating DL TBF
Mar  1 20:20:03 OsmoPCU: DTBF INFO fsm.c:461 TBF[0x83e380]{NEW}: Allocated
Mar  1 20:20:03 OsmoPCU: DTBF INFO fsm.c:461 UL_ASS_TBF[0x838650]{NONE}: Allocated
Mar  1 20:20:03 OsmoPCU: DTBF INFO fsm.c:461 DL_ASS_TBF[0x83bd30]{NONE}: Allocated
Mar  1 20:20:03 OsmoPCU: DRLCMAC INFO gprs_rlcmac_ts_alloc.cpp:943 [DL] algo B <multi> (suggested TRX: 1): using 3 slots
Mar  1 20:20:03 OsmoPCU: DRLCMAC INFO pdch.cpp:1171 PDCH(bts=0,trx=1,ts=4) Attaching TBF(TFI=4 TLLI=0xe5751051 DIR=DL STATE=NEW EGPRS), 3 TBFs, USFs = 00, TFIs = 00000016.
Mar  1 20:20:03 OsmoPCU: DRLCMAC INFO pdch.cpp:1171 PDCH(bts=0,trx=1,ts=5) Attaching TBF(TFI=4 TLLI=0xe5751051 DIR=DL STATE=NEW EGPRS), 6 TBFs, USFs = 07, TFIs = 0000003f.
Mar  1 20:20:03 OsmoPCU: DRLCMAC INFO pdch.cpp:1171 PDCH(bts=0,trx=1,ts=6) Attaching TBF(TFI=4 TLLI=0xe5751051 DIR=DL STATE=NEW EGPRS), 6 TBFs, USFs = 3f, TFIs = 0000003f.
Mar  1 20:20:03 OsmoPCU: DTBF INFO tbf.cpp:345 TBF(TFI=4 TLLI=0xe5751051 DIR=DL STATE=NEW EGPRS) Setting Control TS 5
Mar  1 20:20:03 OsmoPCU: DTBF INFO tbf.cpp:680 TBF(TFI=4 TLLI=0xe5751051 DIR=DL STATE=NEW EGPRS) Allocated: trx = 1, ul_slots = 20, dl_slots = 70
Mar  1 20:20:03 OsmoPCU: DRLCMAC INFO gprs_ms.c:321 MS(TLLI=0xe5751051, IMSI=<ERASED_A>, TA=0, 12/12, UL) Attaching DL TBF: TBF(TFI=4 TLLI=0xe5751051 DIR=DL STATE=NEW EGPRS)
Mar  1 20:20:03 OsmoPCU: DTBFDL INFO tbf_dl.cpp:1380 TBF(TFI=4 TLLI=0xe5751051 DIR=DL STATE=NEW EGPRS) setting EGPRS DL window size to 64, base(64) slots(3) ws_pdch(0)
Mar  1 20:20:03 OsmoPCU: DRLCMAC INFO rlc.cpp:249 ws(64)
Mar  1 20:20:03 OsmoPCU: DTBF INFO tbf_dl.cpp:611 DL_ASS_TBF(UL-TFI_0)[0x8160b0]{NONE}: Received Event SCHED_ASS
Mar  1 20:20:03 OsmoPCU: DTBF INFO tbf_dl_ass_fsm.c:141 DL_ASS_TBF(UL-TFI_0)[0x8160b0]{NONE}: state_chg to SEND_ASS
Mar  1 20:20:03 OsmoPCU: DTBF INFO tbf_dl.cpp:614 TBF(DL-TFI_4)[0x83e380]{NEW}: Received Event ASSIGN_ADD_PACCH
Mar  1 20:20:03 OsmoPCU: DTBF INFO tbf_fsm.c:89 TBF(TFI=4 TLLI=0xe5751051 DIR=DL STATE=NEW EGPRS) set ass. type PACCH [prev CCCH:0, PACCH:0]
Mar  1 20:20:03 OsmoPCU: DTBF INFO tbf_fsm.c:111 TBF(DL-TFI_4)[0x83e380]{NEW}: state_chg to ASSIGN
Mar  1 20:20:03 OsmoPCU: DTBFDL INFO tbf_dl.cpp:983 TBF(TFI=3 TLLI=0xca1cd311 DIR=DL STATE=FLOW EGPRS) Scheduled Ack/Nack polling on FN=628762, TS=6
Mar  1 20:20:03 OsmoPCU: DTBF INFO tbf_dl_ass_fsm.c:249 DL_ASS_TBF(UL-TFI_0)[0x8160b0]{SEND_ASS}: Received Event CREATE_RLCMAC_MSG
Mar  1 20:20:03 OsmoPCU: DTBF INFO tbf_dl_ass_fsm.c:101 TBF(TFI=0 TLLI=0xe5751051 DIR=UL STATE=ASSIGN EGPRS) start Packet Downlink Assignment (PACCH) for TBF(TFI=4 TLLI=0xe5751051 DIR=DL STATE=ASSIGN EGPRS)
Mar  1 20:20:03 OsmoPCU: DTBFDL INFO tbf_dl_ass_fsm.c:122 TBF(TFI=0 TLLI=0xe5751051 DIR=UL STATE=ASSIGN EGPRS) Scheduled DL Assignment polling on PACCH (FN=628762, TS=7)
Mar  1 20:20:03 OsmoPCU: DTBF INFO tbf_dl_ass_fsm.c:159 DL_ASS_TBF(UL-TFI_0)[0x8160b0]{SEND_ASS}: state_chg to WAIT_ACK
Mar  1 20:20:03 OsmoPCU: DRLCMACUL INFO pdch.cpp:1014 PDCH(bts=0,trx=1,ts=5) Got MCS-4 RLC block: R=0, SI=0, TFI=1, CPS=0, RSB=0, rc=385
Mar  1 20:20:03 OsmoPCU: DLBSSGP INFO tbf_ul.cpp:548 LLC [PCU -> SGSN] TBF(TFI=1 TLLI=0xcc5e8e11 DIR=UL STATE=FLOW EGPRS) len=67
Mar  1 20:20:03 OsmoPCU: DLNSDATA INFO gprs_ns2_message.c:426 NSE(00138)-NSVC(00138) Tx NS-UNITDATA
Mar  1 20:20:03 OsmoPCU: DRLCMAC INFO pdch_ul_controller.c:323 PDCH(bts=0,trx=1,ts=6) Timeout for registered USF (FN=628732): TBF(TFI=1 TLLI=0xcc5e8e11 DIR=UL STATE=FLOW EGPRS)
Mar  1 20:20:03 OsmoPCU: DRLCMACUL INFO pdch.cpp:1014 PDCH(bts=0,trx=1,ts=7) Got MCS-4 RLC block: R=0, SI=0, TFI=5, CPS=1, RSB=1, rc=385
Mar  1 20:20:03 OsmoPCU: DTBFUL INFO tbf_ul.cpp:537 UL_ACK_TBF(UL-TFI_5)[0x838a50]{WAIT_ACK}: Received Event SCHED_ACK
Mar  1 20:20:03 OsmoPCU: DTBF INFO tbf_ul_ass_fsm.c:342 UL_ASS_TBF(UL-TFI_0)[0x7cd840]{SEND_ASS}: Received Event CREATE_RLCMAC_MSG
Mar  1 20:20:03 OsmoPCU: DTBF INFO tbf_ul_ass_fsm.c:117 TBF(TFI=0 TLLI=0xe5751051 DIR=UL STATE=ASSIGN EGPRS) start Packet Uplink Assignment (PACCH)
Mar  1 20:20:03 OsmoPCU: DTBFUL INFO tbf_ul_ass_fsm.c:137 TBF(TFI=0 TLLI=0xe5751051 DIR=UL STATE=ASSIGN EGPRS) Scheduled UL Assignment polling on PACCH (FN=628766, TS=7)
Mar  1 20:20:03 OsmoPCU: DTBF INFO tbf_ul_ass_fsm.c:197 UL_ASS_TBF(UL-TFI_0)[0x7cd840]{SEND_ASS}: state_chg to WAIT_ACK
...
Mar  1 20:20:03 OsmoPCU: DTBF NOTICE tbf.cpp:552 TBF(TFI=0 TLLI=0xe5751051 DIR=UL STATE=ASSIGN EGPRS) poll timeout for FN=628762, TS=7 (curr FN 628762)
Mar  1 20:20:03 OsmoPCU: DTBF INFO tbf.cpp:610 DL_ASS_TBF(UL-TFI_0)[0x8160b0]{WAIT_ACK}: Received Event ASS_POLL_TIMEOUT
Mar  1 20:20:03 OsmoPCU: DTBF NOTICE tbf_dl_ass_fsm.c:177 TBF(TFI=0 TLLI=0xe5751051 DIR=UL STATE=ASSIGN EGPRS) Timeout for polling PACKET CONTROL ACK for PACKET DOWNLINK ASSIGNMENT: |Assignment was on PACCH|Uplink data was received|
Mar  1 20:20:03 OsmoPCU: DTBF INFO tbf_dl_ass_fsm.c:179 DL_ASS_TBF(UL-TFI_0)[0x8160b0]{WAIT_ACK}: state_chg to SEND_ASS
Mar  1 20:20:03 OsmoPCU: DTBFDL INFO tbf_dl.cpp:983 TBF(TFI=2 TLLI=0xcc5e8e11 DIR=DL STATE=FLOW EGPRS) Scheduled Ack/Nack polling on FN=628797, TS=5
Mar  1 20:20:03 OsmoPCU: DRLCMACUL INFO pdch.cpp:1014 PDCH(bts=0,trx=1,ts=5) Got MCS-4 RLC block: R=0, SI=0, TFI=1, CPS=0, RSB=0, rc=385
Mar  1 20:20:03 OsmoPCU: DRLCMAC INFO pdch_ul_controller.c:323 PDCH(bts=0,trx=1,ts=6) Timeout for registered USF (FN=628766): TBF(TFI=1 TLLI=0xcc5e8e11 DIR=UL STATE=FLOW EGPRS)
Mar  1 20:20:03 OsmoPCU: DRLCMAC NOTICE pdch_ul_controller.c:330 PDCH(bts=0,trx=1,ts=7) Timeout for registered POLL (FN=628766, reason=UL_ASS): TBF(TFI=0 TLLI=0xe5751051 DIR=UL STATE=ASSIGN EGPRS)
Mar  1 20:20:03 OsmoPCU: DTBF NOTICE tbf.cpp:552 TBF(TFI=0 TLLI=0xe5751051 DIR=UL STATE=ASSIGN EGPRS) poll timeout for FN=628766, TS=7 (curr FN 628766)
Mar  1 20:20:03 OsmoPCU: DTBF NOTICE tbf.cpp:394 TBF(TFI=0 TLLI=0xe5751051 DIR=UL STATE=ASSIGN EGPRS) N3105 exceeded MAX (8)
Mar  1 20:20:03 OsmoPCU: DTBF INFO tbf.cpp:585 TBF(UL-TFI_0)[0x815f00]{ASSIGN}: Received Event MAX_N3105
Mar  1 20:20:03 OsmoPCU: DTBF INFO tbf_fsm.c:194 UL_ASS_TBF(UL-TFI_0)[0x7cd840]{WAIT_ACK}: Received Event ABORT
Mar  1 20:20:03 OsmoPCU: DTBF INFO tbf_fsm.c:196 TBF(UL-TFI_0)[0x815f00]{ASSIGN}: state_chg to RELEASING
...
Mar  1 20:20:06 OsmoPCU: DLBSSGP INFO gprs_bssgp_pcu.c:181 LLC [SGSN -> PCU] = TLLI: 0xe5751051 IMSI: <ERASED_A> len: 62
Mar  1 20:20:06 OsmoPCU: DTBF INFO tbf_dl.cpp:133 MS(TLLI=0xe5751051, IMSI=<ERASED_A>, TA=0, 12/12, UL) Allocating DL TBF
Mar  1 20:20:06 OsmoPCU: DTBF INFO fsm.c:461 TBF[0x83a560]{NEW}: Allocated
Mar  1 20:20:06 OsmoPCU: DTBF INFO fsm.c:461 UL_ASS_TBF[0x838e30]{NONE}: Allocated
Mar  1 20:20:06 OsmoPCU: DTBF INFO fsm.c:461 DL_ASS_TBF[0x881f70]{NONE}: Allocated
Mar  1 20:20:06 OsmoPCU: DRLCMAC INFO gprs_rlcmac_ts_alloc.cpp:943 [DL] algo B <multi> (suggested TRX: 1): using 3 slots
Mar  1 20:20:06 OsmoPCU: DRLCMAC INFO pdch.cpp:1171 PDCH(bts=0,trx=1,ts=4) Attaching TBF(TFI=0 TLLI=0xe5751051 DIR=DL STATE=NEW EGPRS), 3 TBFs, USFs = 00, TFIs = 00000045.
Mar  1 20:20:06 OsmoPCU: DRLCMAC INFO pdch.cpp:1171 PDCH(bts=0,trx=1,ts=5) Attaching TBF(TFI=0 TLLI=0xe5751051 DIR=DL STATE=NEW EGPRS), 5 TBFs, USFs = 05, TFIs = 0000006d.
Mar  1 20:20:06 OsmoPCU: DRLCMAC INFO pdch.cpp:1171 PDCH(bts=0,trx=1,ts=6) Attaching TBF(TFI=0 TLLI=0xe5751051 DIR=DL STATE=NEW EGPRS), 5 TBFs, USFs = 07, TFIs = 0000006d.
Mar  1 20:20:06 OsmoPCU: DTBF INFO tbf.cpp:345 TBF(TFI=0 TLLI=0xe5751051 DIR=DL STATE=NEW EGPRS) Setting Control TS 5
Mar  1 20:20:06 OsmoPCU: DTBF INFO tbf.cpp:680 TBF(TFI=0 TLLI=0xe5751051 DIR=DL STATE=NEW EGPRS) Allocated: trx = 1, ul_slots = 20, dl_slots = 70
Mar  1 20:20:06 OsmoPCU: DRLCMAC INFO gprs_ms.c:321 MS(TLLI=0xe5751051, IMSI=<ERASED_A>, TA=0, 12/12, UL) Attaching DL TBF: TBF(TFI=0 TLLI=0xe5751051 DIR=DL STATE=NEW EGPRS)
Mar  1 20:20:06 OsmoPCU: DTBFDL INFO tbf_dl.cpp:1380 TBF(TFI=0 TLLI=0xe5751051 DIR=DL STATE=NEW EGPRS) setting EGPRS DL window size to 64, base(64) slots(3) ws_pdch(0)
Mar  1 20:20:06 OsmoPCU: DRLCMAC INFO rlc.cpp:249 ws(64)
Mar  1 20:20:06 OsmoPCU: DTBF INFO tbf_dl.cpp:611 DL_ASS_TBF(UL-TFI_0)[0x8160b0]{SEND_ASS}: Received Event SCHED_ASS
Mar  1 20:20:06 OsmoPCU: DTBF ERROR tbf_dl.cpp:611 DL_ASS_TBF(UL-TFI_0)[0x8160b0]{SEND_ASS}: Event SCHED_ASS not permitted  //UNEXPECTED EVENT HERE!!!!
Mar  1 20:20:06 OsmoPCU: DTBF INFO tbf_dl.cpp:614 TBF(DL-TFI_0)[0x83a560]{NEW}: Received Event ASSIGN_ADD_PACCH
Mar  1 20:20:06 OsmoPCU: DTBF INFO tbf_fsm.c:89 TBF(TFI=0 TLLI=0xe5751051 DIR=DL STATE=NEW EGPRS) set ass. type PACCH [prev CCCH:0, PACCH:0]
Mar  1 20:20:06 OsmoPCU: DTBF INFO tbf_fsm.c:111 TBF(DL-TFI_0)[0x83a560]{NEW}: state_chg to ASSIGN
...
Mar  1 20:20:08 OsmoPCU: DRLCMAC INFO pdch_ul_controller.c:323 PDCH(bts=0,trx=1,ts=7) Timeout for registered USF (FN=629845): TBF(TFI=2 TLLI=0xf35df111 DIR=UL STATE=FLOW EGPRS)
Mar  1 20:20:08 OsmoPCU: DTBF INFO fsm.c:322 TBF(UL-TFI_0)[0x815f00]{RELEASING}: Timeout of T3195
Mar  1 20:20:08 OsmoPCU: DTBF INFO tbf.cpp:292 TBF(TFI=0 TLLI=0xe5751051 DIR=UL STATE=RELEASING EGPRS) free
Mar  1 20:20:08 OsmoPCU: DRLCMAC INFO pdch.cpp:1181 PDCH(bts=0,trx=1,ts=5) Detaching TBF(TFI=0 TLLI=0xe5751051 DIR=UL STATE=RELEASING EGPRS), 2 TBFs, USFs = 05, TFIs = 00000003.
Mar  1 20:20:08 OsmoPCU: DRLCMAC INFO pdch.cpp:1181 PDCH(bts=0,trx=1,ts=6) Detaching TBF(TFI=0 TLLI=0xe5751051 DIR=UL STATE=RELEASING EGPRS), 4 TBFs, USFs = 0f, TFIs = 0000000f.
Mar  1 20:20:08 OsmoPCU: DRLCMAC INFO gprs_ms.c:369 MS(TLLI=0xe5751051, IMSI=<ERASED_A>, TA=0, 12/12,) Detaching TBF: TBF(TFI=0 TLLI=0xe5751051 DIR=UL STATE=RELEASING EGPRS)
Mar  1 20:20:08 OsmoPCU: DTBFUL INFO fsm.c:573 UL_ACK_TBF(UL-TFI_0)[0x837630]{NONE}: Deallocated
Mar  1 20:20:08 OsmoPCU: DTBF INFO fsm.c:573 TBF(UL-TFI_0)[0x815f00]{RELEASING}: Deallocated
Mar  1 20:20:08 OsmoPCU: DTBF INFO fsm.c:573 UL_ASS_TBF(UL-TFI_0)[0x7cd840]{WAIT_ACK}: Deallocated
Mar  1 20:20:08 OsmoPCU: DTBF INFO fsm.c:573 DL_ASS_TBF(UL-TFI_0)[0x8160b0]{SEND_ASS}: Deallocated
Actions #1

Updated by pespin 9 months ago

  • Status changed from New to Resolved
  • % Done changed from 0 to 100

The main problem here to start with is that an UL TBF in RELEASE state is selected to initiate the DL TBF assignment over PACCH, which will for sure fail, hence why it is retried (and the assignment is never transmitted by the scheduler since the UL TBF is in RELEASE state).

Situation should be fixed by:
https://gerrit.osmocom.org/c/osmo-pcu/+/33453 Avoid using UL TBF in RELEASE state to assign DL TBF over PACCH

Actions

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)