Cellular Network Infrastructure » Radio Access Network » OsmoPCU

Mar  1 20:18:31 OsmoPCU: DTBF INFO tbf_dl.cpp:758 TBF(DL-TFI_1)[0x814ef0]{FLOW}: Received Event LAST_DL_DATA_SENT
Mar  1 20:18:31 OsmoPCU: DTBF INFO tbf_fsm.c:227 TBF(DL-TFI_1)[0x814ef0]{FLOW}: state_chg to FINISHED
...
Mar  1 20:18:31 OsmoPCU: DRLCMAC INFO pdch_ul_controller.c:323 PDCH(bts=0,trx=1,ts=6) Timeout for registered USF (FN=608794): TBF(TFI=1 TLLI=0xca1cd311 DIR=UL STATE=FLOW EGPRS)
Mar  1 20:18:31 OsmoPCU: DTBFDL INFO tbf_dl.cpp:983 TBF(TFI=1 TLLI=0xca1cd311 DIR=DL STATE=FINISHED EGPRS) Scheduled Ack/Nack polling on FN=608829, TS=5
Mar  1 20:18:31 OsmoPCU: DTBF INFO tbf_dl.cpp:1146 TBF(DL-TFI_1)[0x814ef0]{FINISHED}: Received Event FINAL_ACK_RECVD
Mar  1 20:18:31 OsmoPCU: DTBF INFO tbf_fsm.c:258 TBF(DL-TFI_1)[0x814ef0]{FINISHED}: state_chg to WAIT_RELEASE
Mar  1 20:18:31 OsmoPCU: DTBF INFO tbf_dl.cpp:133 MS(TLLI=0xca1cd311, IMSI=<ERASED_A>, TA=0, 12/12, UL DL) Allocating DL TBF
Mar  1 20:18:31 OsmoPCU: DTBF INFO fsm.c:461 TBF[0x837ae0]{NEW}: Allocated
Mar  1 20:18:31 OsmoPCU: DTBF INFO fsm.c:461 UL_ASS_TBF[0x837cc0]{NONE}: Allocated
Mar  1 20:18:31 OsmoPCU: DTBF INFO fsm.c:461 DL_ASS_TBF[0x7f3370]{NONE}: Allocated
Mar  1 20:18:31 OsmoPCU: DRLCMAC INFO gprs_rlcmac_ts_alloc.cpp:943 [DL] algo B <multi> (suggested TRX: 1): using 3 slots
Mar  1 20:18:31 OsmoPCU: DRLCMAC INFO pdch.cpp:1171 PDCH(bts=0,trx=1,ts=4) Attaching TBF(TFI=3 TLLI=0xca1cd311 DIR=DL STATE=NEW EGPRS), 3 TBFs, USFs = 00, TFIs = 0000000e.
Mar  1 20:18:31 OsmoPCU: DRLCMAC INFO pdch.cpp:1171 PDCH(bts=0,trx=1,ts=5) Attaching TBF(TFI=3 TLLI=0xca1cd311 DIR=DL STATE=NEW EGPRS), 4 TBFs, USFs = 03, TFIs = 0000000f.
Mar  1 20:18:31 OsmoPCU: DRLCMAC INFO pdch.cpp:1171 PDCH(bts=0,trx=1,ts=6) Attaching TBF(TFI=3 TLLI=0xca1cd311 DIR=DL STATE=NEW EGPRS), 4 TBFs, USFs = 0f, TFIs = 0000000f.
Mar  1 20:18:31 OsmoPCU: DTBF INFO tbf.cpp:345 TBF(TFI=3 TLLI=0xca1cd311 DIR=DL STATE=NEW EGPRS) Setting Control TS 5
Mar  1 20:18:31 OsmoPCU: DTBF INFO tbf.cpp:680 TBF(TFI=3 TLLI=0xca1cd311 DIR=DL STATE=NEW EGPRS) Allocated: trx = 1, ul_slots = 20, dl_slots = 70
Mar  1 20:18:31 OsmoPCU: DRLCMAC INFO gprs_ms.c:321 MS(TLLI=0xca1cd311, IMSI=<ERASED_A>, TA=0, 12/12, UL DL) Attaching DL TBF: TBF(TFI=3 TLLI=0xca1cd311 DIR=DL STATE=NEW EGPRS)
Mar  1 20:18:31 OsmoPCU: DTBFDL INFO tbf_dl.cpp:1380 TBF(TFI=3 TLLI=0xca1cd311 DIR=DL STATE=NEW EGPRS) setting EGPRS DL window size to 64, base(64) slots(3) ws_pdch(0)
Mar  1 20:18:31 OsmoPCU: DRLCMAC INFO rlc.cpp:249 ws(64)
Mar  1 20:18:31 OsmoPCU: DTBF INFO tbf_dl.cpp:611 DL_ASS_TBF(DL-TFI_1)[0x83b8f0]{NONE}: Received Event SCHED_ASS
Mar  1 20:18:31 OsmoPCU: DTBF INFO tbf_dl_ass_fsm.c:141 DL_ASS_TBF(DL-TFI_1)[0x83b8f0]{NONE}: state_chg to SEND_ASS
Mar  1 20:18:31 OsmoPCU: DTBF INFO tbf_dl.cpp:614 TBF(DL-TFI_3)[0x837ae0]{NEW}: Received Event ASSIGN_ADD_PACCH
Mar  1 20:18:31 OsmoPCU: DTBF INFO tbf_fsm.c:89 TBF(TFI=3 TLLI=0xca1cd311 DIR=DL STATE=NEW EGPRS) set ass. type PACCH [prev CCCH:0, PACCH:0]
Mar  1 20:18:31 OsmoPCU: DTBF INFO tbf_fsm.c:111 TBF(DL-TFI_3)[0x837ae0]{NEW}: state_chg to ASSIGN
Mar  1 20:18:31 OsmoPCU: DRLCMAC INFO pdch_ul_controller.c:323 PDCH(bts=0,trx=1,ts=6) Timeout for registered USF (FN=608798): TBF(TFI=1 TLLI=0xca1cd311 DIR=UL STATE=FLOW EGPRS)
Mar  1 20:18:31 OsmoPCU: DTBF INFO tbf_dl_ass_fsm.c:249 DL_ASS_TBF(DL-TFI_1)[0x83b8f0]{SEND_ASS}: Received Event CREATE_RLCMAC_MSG
Mar  1 20:18:31 OsmoPCU: DTBF INFO tbf_dl_ass_fsm.c:101 TBF(TFI=1 TLLI=0xca1cd311 DIR=DL STATE=WAIT_RELEASE EGPRS) start Packet Downlink Assignment (PACCH) for TBF(TFI=3 TLLI=0xca1cd311 DIR=DL STATE=ASSIGN EGPRS) // CAN A DL TBF IN WAIT_RELEASE BE USED TO ASSIGN A NEW TBF?!
Mar  1 20:18:31 OsmoPCU: DTBFDL INFO tbf_dl_ass_fsm.c:122 TBF(TFI=1 TLLI=0xca1cd311 DIR=DL STATE=WAIT_RELEASE EGPRS) Scheduled DL Assignment polling on PACCH (FN=608833, TS=5)
Mar  1 20:18:31 OsmoPCU: DTBF INFO tbf_dl_ass_fsm.c:159 DL_ASS_TBF(DL-TFI_1)[0x83b8f0]{SEND_ASS}: state_chg to WAIT_ACK
...
Mar  1 20:18:31 OsmoPCU: DTBF INFO tbf_dl.cpp:1146 TBF(DL-TFI_1)[0x814ef0]{WAIT_RELEASE}: Received Event FINAL_ACK_RECVD  // IT SEEMS WE  POLLED 2 FINAL_ACK, THIS IS THE 2ND ONE WE RECEIVE
Mar  1 20:18:31 OsmoPCU: DTBF INFO tbf_dl.cpp:133 MS(TLLI=0xca1cd311, IMSI=<ERASED_A>, TA=0, 12/12, UL DL) Allocating DL TBF //WE SEEM TO TRIGGER ALLOCATION AGAIN, THOUGH IT'S ALREADY IN PROGRESS FROM ABOVE
Mar  1 20:18:31 OsmoPCU: DTBF INFO fsm.c:461 TBF[0x83cf80]{NEW}: Allocated
Mar  1 20:18:31 OsmoPCU: DTBF INFO fsm.c:461 UL_ASS_TBF[0x83afe0]{NONE}: Allocated
Mar  1 20:18:31 OsmoPCU: DTBF INFO fsm.c:461 DL_ASS_TBF[0x83c740]{NONE}: Allocated
Mar  1 20:18:31 OsmoPCU: DRLCMAC INFO gprs_rlcmac_ts_alloc.cpp:943 [DL] algo B <multi> (suggested TRX: 1): using 3 slots
Mar  1 20:18:31 OsmoPCU: DRLCMAC INFO pdch.cpp:1171 PDCH(bts=0,trx=1,ts=4) Attaching TBF(TFI=5 TLLI=0xca1cd311 DIR=DL STATE=NEW EGPRS), 5 TBFs, USFs = 00, TFIs = 0000003e.
Mar  1 20:18:31 OsmoPCU: DRLCMAC INFO pdch.cpp:1171 PDCH(bts=0,trx=1,ts=5) Attaching TBF(TFI=5 TLLI=0xca1cd311 DIR=DL STATE=NEW EGPRS), 6 TBFs, USFs = 03, TFIs = 0000003f.
Mar  1 20:18:31 OsmoPCU: DRLCMAC INFO pdch.cpp:1171 PDCH(bts=0,trx=1,ts=6) Attaching TBF(TFI=5 TLLI=0xca1cd311 DIR=DL STATE=NEW EGPRS), 6 TBFs, USFs = 0f, TFIs = 0000003f.
Mar  1 20:18:31 OsmoPCU: DTBF INFO tbf.cpp:345 TBF(TFI=5 TLLI=0xca1cd311 DIR=DL STATE=NEW EGPRS) Setting Control TS 5
Mar  1 20:18:31 OsmoPCU: DTBF INFO tbf.cpp:680 TBF(TFI=5 TLLI=0xca1cd311 DIR=DL STATE=NEW EGPRS) Allocated: trx = 1, ul_slots = 20, dl_slots = 70
Mar  1 20:18:31 OsmoPCU: DRLCMAC INFO gprs_ms.c:321 MS(TLLI=0xca1cd311, IMSI=IMSI=<ERASED_A>, TA=0, 12/12, UL DL) Attaching DL TBF: TBF(TFI=5 TLLI=0xca1cd311 DIR=DL STATE=NEW EGPRS) // A NEW DL TBF TFI=5 IS CREATED FOR SAME MS
Mar  1 20:18:31 OsmoPCU: DTBFDL INFO tbf_dl.cpp:1380 TBF(TFI=5 TLLI=0xca1cd311 DIR=DL STATE=NEW EGPRS) setting EGPRS DL window size to 64, base(64) slots(3) ws_pdch(0)
Mar  1 20:18:31 OsmoPCU: DRLCMAC INFO rlc.cpp:249 ws(64)
Mar  1 20:18:31 OsmoPCU: DTBF INFO tbf_dl.cpp:611 DL_ASS_TBF(DL-TFI_1)[0x83b8f0]{WAIT_ACK}: Received Event SCHED_ASS  //SCHED FOR A NEW DL TBF ASS
Mar  1 20:18:31 OsmoPCU: DTBF ERROR tbf_dl.cpp:611 DL_ASS_TBF(DL-TFI_1)[0x83b8f0]{WAIT_ACK}: Event SCHED_ASS not permitted  // BUT IT IS IN STATE WAIT_ACK, ALREADY PROCESSING ONE!
...
Mar  1 20:18:31 OsmoPCU: DTBF INFO pdch.cpp:435 DL_ASS_TBF(DL-TFI_1)[0x83b8f0]{WAIT_ACK}: Received Event RX_ASS_CTRL_ACK  // HERE HE ACK IT WAS WAITING FOR ARRIVES 
Mar  1 20:18:31 OsmoPCU: DTBF INFO tbf_dl_ass_fsm.c:172 DL_ASS_TBF(DL-TFI_1)[0x83b8f0]{WAIT_ACK}: state_chg to NONE
Mar  1 20:18:31 OsmoPCU: DTBF INFO tbf.cpp:292 TBF(TFI=1 TLLI=0xca1cd311 DIR=DL STATE=WAIT_RELEASE EGPRS) free   //DL TBF TFI=1 IS FREED AFTER RECEIVING CTRL ACK
Mar  1 20:18:31 OsmoPCU: DRLCMAC INFO pdch.cpp:1181 PDCH(bts=0,trx=1,ts=4) Detaching TBF(TFI=1 TLLI=0xca1cd311 DIR=DL STATE=WAIT_RELEASE EGPRS), 5 TBFs, USFs = 00, TFIs = 0000003e.
Mar  1 20:18:31 OsmoPCU: DRLCMAC INFO pdch.cpp:1181 PDCH(bts=0,trx=1,ts=5) Detaching TBF(TFI=1 TLLI=0xca1cd311 DIR=DL STATE=WAIT_RELEASE EGPRS), 6 TBFs, USFs = 03, TFIs = 0000003f.
Mar  1 20:18:31 OsmoPCU: DRLCMAC INFO pdch.cpp:1181 PDCH(bts=0,trx=1,ts=6) Detaching TBF(TFI=1 TLLI=0xca1cd311 DIR=DL STATE=WAIT_RELEASE EGPRS), 6 TBFs, USFs = 0f, TFIs = 0000003f.
Mar  1 20:18:31 OsmoPCU: DRLCMAC INFO gprs_ms.c:369 MS(TLLI=0xca1cd311, IMSI=<ERASED_A>, TA=0, 12/12, UL DL) Detaching TBF: TBF(TFI=1 TLLI=0xca1cd311 DIR=DL STATE=WAIT_RELEASE EGPRS)
Mar  1 20:18:31 OsmoPCU: DTBF INFO fsm.c:573 TBF(DL-TFI_1)[0x814ef0]{WAIT_RELEASE}: Deallocated
Mar  1 20:18:31 OsmoPCU: DTBF INFO fsm.c:573 UL_ASS_TBF(DL-TFI_1)[0x8392c0]{NONE}: Deallocated
Mar  1 20:18:31 OsmoPCU: DTBF INFO fsm.c:573 DL_ASS_TBF(DL-TFI_1)[0x83b8f0]{NONE}: Deallocated

I'm not sure right now how it comes a DL TBF which received a FINAL ACK can still receive a RX_ASS_CTRL_ACK later, since after FINAL ACK the MS is not listening anymore? Maybe the MS already knows from before it should answer it?
It seems we trigger the creation of a new DL TBF when receiving FINAL_ACK_RECVD even if the TBF is already in WAIT_RELEASE (which means we should have received one). We should ignore that even if we are already in WAIT_RELEASE afaict. This would mean we avoid everything coming afterwards.