Project

General

Profile

Actions

Bug #6206

closed

modem: "UL_TBF_ASS[0x5570b55bf0]{IDLE}: Event CREATE_RLCMAC_MSG not permitted"

Added by fixeria 5 months ago. Updated 5 months ago.

Status:
Resolved
Priority:
High
Assignee:
Category:
-
Target version:
Start date:
10/05/2023
Due date:
% Done:

0%

Resolution:
Spec Reference:
Tags:

Description

Somehow I am unable to attach to the network anymore, most likely due to the following error:

20231004210952228 DGMM INFO gmm_prim.c:809 Rx from lower layers: LL-UNITDATA.indication
20231004210952228 DGMM INFO gmm.c:1248 GMME(IMSI-001010000000101:PTMSI-11223344:TLLI-91223344) Rx GMM IDENTITY REQUEST mi_type=IMEI force_stdby=0
20231004210952228 DGMM INFO gmm.c:571 GMME(IMSI-001010000000101:PTMSI-11223344:TLLI-91223344) Tx GMM IDENTITY RESPONSE
20231004210952228 DLLC INFO llc_prim.c:157 Rx from upper layers: LL-UNITDATA.request    
20231004210952229 DLLC DEBUG llc.c:145 modem_llc_prim_down_cb(): Rx GRR-UNITDATA.request ll=[01 c0 05 08 16 08 0a 00 00 00 00 00 21 43 ba 61 ac ]
20231004210952229 DRLCMAC INFO rlcmac_prim.c:522 Rx from upper layers: GRR-UNITDATA.request
20231004210952270 DRLCMAC INFO fsm.c:456 UL_TBF[0x5570b55ac0]{NEW}: Allocated
20231004210952270 DRLCMAC INFO fsm.c:456 UL_TBF_ASS[0x5570b55bf0]{IDLE}: Allocated
20231004210952270 DRLCMAC INFO tbf_ul_ass_fsm.c:709 UL_TBF_ASS[0x5570b55bf0]{IDLE}: Received Event START_FROM_DL_TBF
20231004210952270 DRLCMAC INFO tbf_ul_ass_fsm.c:301 UL_TBF[0x5570b55ac0]{NEW}: Received Event UL_ASS_START
20231004210952270 DRLCMAC INFO tbf_ul_fsm.c:148 UL_TBF[0x5570b55ac0]{NEW}: state_chg to ASSIGN
20231004210952270 DRLCMAC INFO tbf_ul_ass_fsm.c:303 UL_TBF_ASS[0x5570b55bf0]{IDLE}: state_chg to WAIT_PKT_UL_ASS
20231004210952370 DRLCMAC INFO rlcmac.c:793 TS=3 FN=1928173 Rx Pkt UL ASS
20231004210952370 DRLCMAC INFO tbf_ul.c:343 UL_TBF_ASS[0x5570b55bf0]{WAIT_PKT_UL_ASS}: Received Event RX_PKT_UL_ASS
20231004210952370 DRLCMAC INFO tbf_ul_ass_fsm.c:426 UL_TBF_ASS[0x5570b55bf0]{WAIT_PKT_UL_ASS}: state_chg to COMPLETED
20231004210952370 DRLCMAC INFO tbf_ul_ass_fsm.c:515 UL_TBF[0x5570b55ac0]{ASSIGN}: Received Event UL_ASS_COMPL
20231004210952370 DRLCMAC INFO tbf_ul.c:130 TBF(UL:NR-1:TLLI-91223344) Send L1CTL-CFG_UL_TBF.req ul_tbf_nr=1 ul_slotmask=0x08 tbf_starting_time(present=0 fn=0)   
20231004210952371 DRLCMAC INFO tbf_ul_fsm.c:162 UL_TBF[0x5570b55ac0]{ASSIGN}: state_chg to FLOW
20231004210952371 DRLCMAC INFO tbf_ul_ass_fsm.c:517 UL_TBF_ASS[0x5570b55bf0]{COMPLETED}: state_chg to IDLE
20231004210952389 DRLCMAC INFO rlcmac.c:793 TS=3 FN=1928177 Rx Pkt DL Dummy Ctrl Block
20231004210952408 DRLCMAC INFO rlcmac.c:793 TS=3 FN=1928181 Rx Pkt DL Dummy Ctrl Block
20231004210952408 DRLCMAC INFO tbf_ul_ass_fsm.c:798 UL_TBF_ASS[0x5570b55bf0]{IDLE}: Received Event CREATE_RLCMAC_MSG
20231004210952408 DRLCMAC ERROR tbf_ul_ass_fsm.c:798 UL_TBF_ASS[0x5570b55bf0]{IDLE}: Event CREATE_RLCMAC_MSG not permitted

AFAICS, the PCU allocates us an Uplink TBF and we're trying to ACK it, but failing to do so (CREATE_RLCMAC_MSG not permitted).

osmocom-bb.git 615a88f69b52e786abab2001cb442329439711dc
libosmo-gprs.git 5162449b71c4285e6c032fb0df39e8c1ba86835d

100% (5/5 times) reproduceable on the mssdr-ms host.

It should be noted that I have disabled osmo-pcu's power saving mode by hacking the code (needed for debugging #6200).


Related issues

Blocks OsmocomBB - Bug #6200: osmo-trx-ms: lots of @Received bad frame (rc=-1, ber=444/444)@NewHoernchen10/03/2023

Actions
Actions #1

Updated by fixeria 5 months ago

fixeria wrote:

It should be noted that I have disabled osmo-pcu's power saving mode by hacking the code (needed for debugging #6200).

I just tried resetting osmo-pcu.git back to the clean state and thus re-enabling the power saving mode - no luck, same behavior.

FYI: osmo-pcu.git 24a2ac99d4fcbea18ac90ad88c6116179c5a71c2

Actions #2

Updated by pespin 5 months ago

fixeria this looks like the bug I fixed and merged yesterday in libosmo-gprs.
The ul_tbf_ass_fsm is going to COMPLETE state before waiting for the scheduler to request transmission of the Pkt Ctrl Ack.

Actions #3

Updated by fixeria 5 months ago

  • Blocks Bug #6200: osmo-trx-ms: lots of @Received bad frame (rc=-1, ber=444/444)@ added
Actions #4

Updated by fixeria 5 months ago

Here is some additional logging, as you requested:

20231005141903950 DGMM INFO gmm.c:571 GMME(IMSI-001010000000101:PTMSI-11223344:TLLI-91223344) Tx GMM IDENTITY RESPONSE
20231005141903950 DLLC INFO llc_prim.c:157 Rx from upper layers: LL-UNITDATA.request
20231005141903950 DLLC DEBUG llc.c:145 modem_llc_prim_down_cb(): Rx GRR-UNITDATA.request ll=[01 c0 05 08 16 08 0a 00 00 00 00 00 21 43 ba 61 ac ]
20231005141903950 DRLCMAC INFO rlcmac_prim.c:522 Rx from upper layers: GRR-UNITDATA.request
20231005141903987 DRLCMAC INFO fsm.c:456 UL_TBF[0x5574330e80]{NEW}: Allocated
20231005141903987 DRLCMAC INFO fsm.c:456 UL_TBF_ASS[0x5574330fb0]{IDLE}: Allocated
20231005141903987 DRLCMAC INFO tbf_ul_ass_fsm.c:711 UL_TBF_ASS[0x5574330fb0]{IDLE}: Received Event START_FROM_DL_TBF
20231005141903987 DRLCMAC INFO tbf_ul_ass_fsm.c:301 UL_TBF[0x5574330e80]{NEW}: Received Event UL_ASS_START
20231005141903987 DRLCMAC INFO tbf_ul_fsm.c:148 UL_TBF[0x5574330e80]{NEW}: state_chg to ASSIGN
20231005141903987 DRLCMAC INFO tbf_ul_ass_fsm.c:303 UL_TBF_ASS[0x5574330fb0]{IDLE}: state_chg to WAIT_PKT_UL_ASS
20231005141904107 DRLCMAC INFO rlcmac.c:793 TS=3 FN=1729476 Rx Pkt UL ASS 
20231005141904107 DRLCMAC INFO tbf_ul.c:343 UL_TBF_ASS[0x5574330fb0]{WAIT_PKT_UL_ASS}: Received Event RX_PKT_UL_ASS
20231005141904107 DRLCMAC NOTICE tbf_ul_ass_fsm.c:407 UL_TBF_ASS[0x5574330fb0]{WAIT_PKT_UL_ASS}: PESPIN: Rx Pkt Ul Ass: curr_fn=1729476 S/P=1
20231005141904107 DRLCMAC NOTICE tbf_ul_ass_fsm.c:411 UL_TBF_ASS[0x5574330fb0]{WAIT_PKT_UL_ASS}: PESPIN: Rx Pkt Ul Ass: poll_fn=1729489 reserve_fn=1729498 start_time_exists=0 start_time=0
20231005141904107 DRLCMAC INFO tbf_ul_ass_fsm.c:428 UL_TBF_ASS[0x5574330fb0]{WAIT_PKT_UL_ASS}: state_chg to COMPLETED
20231005141904107 DRLCMAC INFO tbf_ul_ass_fsm.c:517 UL_TBF[0x5574330e80]{ASSIGN}: Received Event UL_ASS_COMPL
20231005141904107 DRLCMAC INFO tbf_ul.c:130 TBF(UL:NR-1:TLLI-91223344) Send L1CTL-CFG_UL_TBF.req ul_tbf_nr=1 ul_slotmask=0x08 tbf_starting_time(present=0 fn=0)
20231005141904107 DRLCMAC INFO tbf_ul_fsm.c:162 UL_TBF[0x5574330e80]{ASSIGN}: state_chg to FLOW
20231005141904107 DRLCMAC INFO tbf_ul_ass_fsm.c:519 UL_TBF_ASS[0x5574330fb0]{COMPLETED}: state_chg to IDLE
20231005141904129 DRLCMAC INFO rlcmac.c:793 TS=3 FN=1729481 Rx Pkt DL Dummy Ctrl Block
20231005141904148 DRLCMAC INFO rlcmac.c:793 TS=3 FN=1729485 Rx Pkt DL Dummy Ctrl Block
20231005141904148 DRLCMAC INFO tbf_ul_ass_fsm.c:800 UL_TBF_ASS[0x5574330fb0]{IDLE}: Received Event CREATE_RLCMAC_MSG
20231005141904148 DRLCMAC ERROR tbf_ul_ass_fsm.c:800 UL_TBF_ASS[0x5574330fb0]{IDLE}: Event CREATE_RLCMAC_MSG not permitted
Actions #5

Updated by pespin 5 months ago

  • Status changed from New to Feedback
  • Assignee changed from pespin to fixeria

Related fix (among others):
https://gerrit.osmocom.org/c/libosmo-gprs/+/34667 rlcmac: tbf_ul_ass_fsm: Fix logic delay starting time

Actions #6

Updated by fixeria 5 months ago

  • Status changed from Feedback to Resolved

Thanks, I am no longer seeing this error.

Actions

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)