Bug #6206
closed
modem: "UL_TBF_ASS[0x5570b55bf0]{IDLE}: Event CREATE_RLCMAC_MSG not permitted"
Added by fixeria 7 months ago.
Updated 7 months ago.
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).
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
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.
- Blocks Bug #6200: osmo-trx-ms: lots of @Received bad frame (rc=-1, ber=444/444)@ added
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
- Status changed from New to Feedback
- Assignee changed from pespin to fixeria
- Status changed from Feedback to Resolved
Thanks, I am no longer seeing this error.
Also available in: Atom
PDF
