https://osmocom.org/https://osmocom.org/favicon.ico?16647414092021-11-06T03:34:51ZOpen Source Mobile CommunicationsOsmoPCU - Bug #5293: Assert failed pdch != NULL encoding.cpp:561https://osmocom.org/issues/5293?journal_id=229252021-11-06T03:34:51Zkeith
<ul></ul><p>Somehow I lost the process in gdb, but here's a slightly better backtrace....</p>
<pre>
#2 0xb6eba0d8 in osmo_panic () from /usr/lib/libosmocore.so.17
#3 0x0005a574 in gen_freq_params(Frequency_Parameters_t*, gprs_rlcmac_tbf const*) ()
#4 0x0005a92c in write_packet_uplink_assignment ()
#5 0x00043bd0 in create_packet_ul_assign (ctx=0x380ed0, d=0xbefff9d0) at tbf_ul_ass_fsm.c:116
#6 0x000440ec in st_send_ass (fi=0x1f4088, event=2, data=0xbefff9d0) at tbf_ul_ass_fsm.c:189
#7 0xb6eb0480 in _osmo_fsm_inst_dispatch () from /usr/lib/libosmocore.so.17
#8 0x00044678 in tbf_ul_ass_create_rlcmac_msg (tbf=0x361858, fn=650377, ts=7 '\a') at tbf_ul_ass_fsm.c:337
#9 0x000684dc in sched_select_ctrl_msg(gprs_rlcmac_pdch*, unsigned int, unsigned char, tbf_sched_candidates*) ()
#10 0x00069684 in gprs_rlcmac_rcv_rts_block(gprs_rlcmac_bts*, unsigned char, unsigned char, unsigned int, unsigned char) ()
#11 0x00028ca8 in pcu_rx_rts_req_pdtch ()
#12 0x00015f7c in handle_ph_readytosend_ind (fl1h=0x16b7d8, rts_ind=0x2393d8) at osmo-bts-sysmo/sysmo_l1_if.c:148
#13 0x00016768 in l1if_handle_l1prim (wq=3, fl1h=0x16b7d8, msg=0x239310) at osmo-bts-sysmo/sysmo_l1_if.c:287
#14 0x00016f60 in l1if_fd_cb (ofd=0x16b888, what=1) at osmo-bts-sysmo/sysmo_l1_hw.c:118
</pre>
<p>and some lead up log...</p>
<pre>
DRLCMAC NOTICE <0002> pdch_ul_controller.c:330 PDCH(bts=0,trx=0,ts=7) Timeout for registered POLL (FN=650346, reason=UL_ASS): TBF(TFI=8 TLLI=0xb065b200 DIR=UL STATE=ASSIGN EGPRS)
DTBF NOTICE <0008> tbf.cpp:550 TBF(TFI=8 TLLI=0xb065b200 DIR=UL STATE=ASSIGN EGPRS) poll timeout for FN=650346, TS=7 (curr FN 650346)
DTBF INFO <0008> tbf.cpp:589 UL_ASS_TBF(UL-TFI_8)[0x1f5a88]{WAIT_ACK}: Received Event ASS_POLL_TIMEOUT
DTBF NOTICE <0008> tbf_ul_ass_fsm.c:236 TBF(TFI=8 TLLI=0xb065b200 DIR=UL STATE=ASSIGN EGPRS) Timeout for polling PACKET CONTROL ACK for PACKET UPLINK ASSIGNMENT: |Assignment was on PACCH
|No uplink data received yet|
DTBF INFO <0008> tbf_ul_ass_fsm.c:239 UL_ASS_TBF(UL-TFI_8)[0x1f5a88]{WAIT_ACK}: state_chg to SEND_ASS
DTBF INFO <0008> tbf_ul_ass_fsm.c:337 UL_ASS_TBF(UL-TFI_4)[0x2bcb38]{SEND_ASS}: Received Event CREATE_RLCMAC_MSG
DTBF INFO <0008> tbf_ul_ass_fsm.c:192 UL_ASS_TBF(UL-TFI_4)[0x2bcb38]{SEND_ASS}: state_chg to WAIT_ACK
DTBF INFO <0008> tbf_ul.cpp:119 MS(TLLI=0x7ab5508e, IMSI=, TA=1, 12/12, UL) Allocating UL TBF
DTBF INFO <0008> ../../git/src/fsm.c:461 TBF[0x2406a0]{NEW}: Allocated
DTBF INFO <0008> ../../git/src/fsm.c:461 UL_ASS_TBF[0x1f7438]{NONE}: Allocated
DTBF INFO <0008> ../../git/src/fsm.c:461 DL_ASS_TBF[0x1f7528]{NONE}: Allocated
DRLCMAC NOTICE <0002> gprs_rlcmac_ts_alloc.cpp:775 No USF available
DRLCMAC NOTICE <0002> gprs_rlcmac_ts_alloc.cpp:394 [UL] algo A <multi> (suggested TRX: 0): failed to allocate a TS, no USF available
DTBF NOTICE <0008> tbf.cpp:667 TBF(TFI=0 TLLI=0x7ab5508e DIR=UL STATE=NEW EGPRS) Timeslot Allocation failed: trx = 0, single_slot = 0
DTBF INFO <0008> ../../git/src/fsm.c:573 TBF[0x2406a0]{NEW}: Deallocated
DTBF INFO <0008> ../../git/src/fsm.c:573 UL_ASS_TBF[0x1f7438]{NONE}: Deallocated
DTBF INFO <0008> ../../git/src/fsm.c:573 DL_ASS_TBF[0x1f7528]{NONE}: Deallocated
DTBF NOTICE <0008> tbf_ul.cpp:161 MS(TLLI=0x7ab5508e, IMSI=, TA=1, 12/12, UL) No PDCH resource
DTBF INFO <0008> ../../git/src/fsm.c:461 TBF[0x2406a0]{NEW}: Allocated
DTBF INFO <0008> ../../git/src/fsm.c:461 UL_ASS_TBF[0x1f7438]{NONE}: Allocated
DTBF INFO <0008> ../../git/src/fsm.c:461 DL_ASS_TBF[0x1f7528]{NONE}: Allocated
DTBF INFO <0008> tbf_ul.cpp:224 TBF[0x2406a0]{NEW}: Received Event ASSIGN_ADD_PACCH
DTBF INFO <0008> tbf_fsm.c:89 TBF(TFI=0 TLLI=0x7ab5508e DIR=UL STATE=NEW) set ass. type PACCH [prev CCCH:0, PACCH:0]
DTBF INFO <0008> tbf_fsm.c:111 TBF[0x2406a0]{NEW}: state_chg to ASSIGN
DTBF INFO <0008> tbf_ul.cpp:225 UL_ASS_TBF[0x1f7438]{NONE}: Received Event SCHED_ASS_REJ
DTBF INFO <0008> tbf_ul_ass_fsm.c:171 UL_ASS_TBF[0x1f7438]{NONE}: state_chg to SEND_ASS_REJ
DTBF INFO <0008> tbf_ul_ass_fsm.c:337 UL_ASS_TBF(UL-TFI_8)[0x1f5a88]{SEND_ASS}: Received Event CREATE_RLCMAC_MSG
DTBF INFO <0008> tbf_ul_ass_fsm.c:192 UL_ASS_TBF(UL-TFI_8)[0x1f5a88]{SEND_ASS}: state_chg to WAIT_ACK
DRLCMAC NOTICE <0002> pdch_ul_controller.c:330 PDCH(bts=0,trx=0,ts=7) Timeout for registered POLL (FN=650355, reason=UL_ASS): TBF(TFI=7 TLLI=0x965a444a DIR=UL STATE=ASSIGN EGPRS)
DTBF NOTICE <0008> tbf.cpp:550 TBF(TFI=7 TLLI=0x965a444a DIR=UL STATE=ASSIGN EGPRS) poll timeout for FN=650355, TS=7 (curr FN 650355)
DTBF INFO <0008> tbf.cpp:589 UL_ASS_TBF(UL-TFI_7)[0x1f29d0]{WAIT_ACK}: Received Event ASS_POLL_TIMEOUT
DTBF NOTICE <0008> tbf_ul_ass_fsm.c:236 TBF(TFI=7 TLLI=0x965a444a DIR=UL STATE=ASSIGN EGPRS) Timeout for polling PACKET CONTROL ACK for PACKET UPLINK ASSIGNMENT: |Assignment was on PACCH
|Uplink data was received|
DTBF INFO <0008> tbf_ul_ass_fsm.c:239 UL_ASS_TBF(UL-TFI_7)[0x1f29d0]{WAIT_ACK}: state_chg to SEND_ASS
DTBF INFO <0008> tbf_ul_ass_fsm.c:337 UL_ASS_TBF(UL-TFI_7)[0x1f29d0]{SEND_ASS}: Received Event CREATE_RLCMAC_MSG
DTBF INFO <0008> tbf_ul_ass_fsm.c:192 UL_ASS_TBF(UL-TFI_7)[0x1f29d0]{SEND_ASS}: state_chg to WAIT_ACK
DRLCMAC NOTICE <0002> pdch_ul_controller.c:330 PDCH(bts=0,trx=0,ts=7) Timeout for registered POLL (FN=650359, reason=UL_ASS): TBF(TFI=13 TLLI=0xb44dffdf DIR=UL STATE=ASSIGN EGPRS)
DTBF NOTICE <0008> tbf.cpp:550 TBF(TFI=13 TLLI=0xb44dffdf DIR=UL STATE=ASSIGN EGPRS) poll timeout for FN=650359, TS=7 (curr FN 650359)
DTBF INFO <0008> tbf.cpp:589 UL_ASS_TBF(UL-TFI_13)[0x241cb8]{WAIT_ACK}: Received Event ASS_POLL_TIMEOUT
DTBF NOTICE <0008> tbf_ul_ass_fsm.c:236 TBF(TFI=13 TLLI=0xb44dffdf DIR=UL STATE=ASSIGN EGPRS) Timeout for polling PACKET CONTROL ACK for PACKET UPLINK ASSIGNMENT: |Assignment was on PACC
H|No uplink data received yet|
DTBF INFO <0008> tbf_ul_ass_fsm.c:239 UL_ASS_TBF(UL-TFI_13)[0x241cb8]{WAIT_ACK}: state_chg to SEND_ASS
DTBF INFO <0008> tbf_ul_ass_fsm.c:337 UL_ASS_TBF(UL-TFI_13)[0x241cb8]{SEND_ASS}: Received Event CREATE_RLCMAC_MSG
DTBF INFO <0008> tbf_ul_ass_fsm.c:192 UL_ASS_TBF(UL-TFI_13)[0x241cb8]{SEND_ASS}: state_chg to WAIT_ACK
DRLCMACUL NOTICE <0005> pdch.cpp:996 PDCH(bts=0,trx=0,ts=5) FN=650364 Rx UL DATA from unexpected TBF(TFI=9 TLLI=0x979f328f DIR=UL STATE=FINISHED EGPRS) vs expected POLL TBF(TFI=9 TLLI=0x
979f328f DIR=UL STATE=FINISHED EGPRS) reason=DL_ASS
DRLCMAC NOTICE <0002> pdch_ul_controller.c:330 PDCH(bts=0,trx=0,ts=5) Timeout for registered POLL (FN=650364, reason=DL_ASS): TBF(TFI=9 TLLI=0x979f328f DIR=UL STATE=FINISHED EGPRS)
DTBF NOTICE <0008> tbf.cpp:550 TBF(TFI=9 TLLI=0x979f328f DIR=UL STATE=FINISHED EGPRS) poll timeout for FN=650364, TS=5 (curr FN 650364)
DTBF INFO <0008> tbf.cpp:608 DL_ASS_TBF(UL-TFI_9)[0x218e48]{WAIT_ACK}: Received Event ASS_POLL_TIMEOUT
DTBF NOTICE <0008> tbf_dl_ass_fsm.c:175 TBF(TFI=9 TLLI=0x979f328f DIR=UL STATE=FINISHED EGPRS) Timeout for polling PACKET CONTROL ACK for PACKET DOWNLINK ASSIGNMENT: |Assignment was on P
ACCH|Uplink data was received|
DTBF INFO <0008> tbf_dl_ass_fsm.c:177 DL_ASS_TBF(UL-TFI_9)[0x218e48]{WAIT_ACK}: state_chg to SEND_ASS
DRLCMAC NOTICE <0002> pdch_ul_controller.c:330 PDCH(bts=0,trx=0,ts=7) Timeout for registered POLL (FN=650364, reason=UL_ASS): TBF(TFI=10 TLLI=0x7ab5508e DIR=UL STATE=ASSIGN EGPRS)
DTBF NOTICE <0008> tbf.cpp:550 TBF(TFI=10 TLLI=0x7ab5508e DIR=UL STATE=ASSIGN EGPRS) poll timeout for FN=650364, TS=7 (curr FN 650364)
DTBF INFO <0008> tbf.cpp:589 UL_ASS_TBF(UL-TFI_10)[0x1f4088]{WAIT_ACK}: Received Event ASS_POLL_TIMEOUT
DTBF NOTICE <0008> tbf_ul_ass_fsm.c:236 TBF(TFI=10 TLLI=0x7ab5508e DIR=UL STATE=ASSIGN EGPRS) Timeout for polling PACKET CONTROL ACK for PACKET UPLINK ASSIGNMENT: |Assignment was on PACC
H|No uplink data received yet|
DTBF INFO <0008> tbf_ul_ass_fsm.c:239 UL_ASS_TBF(UL-TFI_10)[0x1f4088]{WAIT_ACK}: state_chg to SEND_ASS
DTBF INFO <0008> tbf_dl_ass_fsm.c:249 DL_ASS_TBF(UL-TFI_9)[0x218e48]{SEND_ASS}: Received Event CREATE_RLCMAC_MSG
DTBF INFO <0008> tbf_dl_ass_fsm.c:102 TBF(TFI=2 TLLI=0x979f328f DIR=DL STATE=ASSIGN EGPRS) start Packet Downlink Assignment (PACCH)
DTBF INFO <0008> tbf_dl_ass_fsm.c:157 DL_ASS_TBF(UL-TFI_9)[0x218e48]{SEND_ASS}: state_chg to WAIT_ACK
DTBF INFO <0008> ../../git/src/fsm.c:322 TBF(DL-TFI_0)[0x2438f8]{ASSIGN}: Timeout of X2001
DTBF NOTICE <0008> tbf_fsm.c:391 TBF(TFI=0 TLLI=0x8c461857 DIR=DL STATE=ASSIGN EGPRS) releasing due to PACCH assignment timeout.
DTBF INFO <0008> tbf.cpp:290 TBF(TFI=0 TLLI=0x8c461857 DIR=DL STATE=ASSIGN EGPRS) free
DTBF INFO <0008> ../../git/src/fsm.c:573 TBF(DL-TFI_0)[0x2438f8]{ASSIGN}: Deallocated
DTBF INFO <0008> ../../git/src/fsm.c:573 UL_ASS_TBF(DL-TFI_0)[0x241168]{NONE}: Deallocated
DTBF INFO <0008> ../../git/src/fsm.c:573 DL_ASS_TBF(DL-TFI_0)[0x1f4ec0]{NONE}: Deallocated
DTBF INFO <0008> tbf_ul_ass_fsm.c:337 UL_ASS_TBF(UL-TFI_10)[0x1f4088]{SEND_ASS}: Received Event CREATE_RLCMAC_MSG
</pre> OsmoPCU - Bug #5293: Assert failed pdch != NULL encoding.cpp:561https://osmocom.org/issues/5293?journal_id=229262021-11-06T04:40:34Zkeith
<ul></ul><p>Once Again. <br /><em><br />I don't know why I don't have any symbol table in write_packet_uplink_assignment() any seem to be missing struct gprs_rlcmac_ul_tbf? I compliled this with -O0 and -g (still not sure if that's best)</em></p>
<pre>
(gdb) p new_tbf
$4 = (struct gprs_rlcmac_ul_tbf *) 0x4ff998
(gdb) p *new_tbf
$5 = <incomplete type>
(gdb) p (struct gprs_rlcmac_ul_tbf *) new_tbf
No struct type named gprs_rlcmac_ul_tbf.
</pre><br />Sending on core and binary anyway.
<pre>
(gdb) bt
#0 0x425bcf74 in raise () from /lib/libc.so.6
#1 0x425be358 in abort () from /lib/libc.so.6
#2 0xb6eba0d8 in osmo_panic () from /usr/lib/libosmocore.so.17
#3 0x0005a574 in gen_freq_params(Frequency_Parameters_t*, gprs_rlcmac_tbf const*) ()
#4 0x0005a92c in write_packet_uplink_assignment ()
#5 0x00043bd0 in create_packet_ul_assign (ctx=0x3fab80, d=0xbefff9d0) at tbf_ul_ass_fsm.c:116
#6 0x000440ec in st_send_ass (fi=0x1bfe30, event=2, data=0xbefff9d0) at tbf_ul_ass_fsm.c:189
#7 0xb6eb0480 in _osmo_fsm_inst_dispatch () from /usr/lib/libosmocore.so.17
#8 0x00044678 in tbf_ul_ass_create_rlcmac_msg (tbf=0x3db508, fn=1502366, ts=7 '\a') at tbf_ul_ass_fsm.c:337
#9 0x000684dc in sched_select_ctrl_msg(gprs_rlcmac_pdch*, unsigned int, unsigned char, tbf_sched_candidates*) ()
#10 0x00069684 in gprs_rlcmac_rcv_rts_block(gprs_rlcmac_bts*, unsigned char, unsigned char, unsigned int, unsigned char) ()
#11 0x00028ca8 in pcu_rx_rts_req_pdtch ()
#12 0x00015f7c in handle_ph_readytosend_ind (fl1h=0x16b7d8, rts_ind=0x1c2488) at osmo-bts-sysmo/sysmo_l1_if.c:148
#13 0x00016768 in l1if_handle_l1prim (wq=3, fl1h=0x16b7d8, msg=0x1c23c0) at osmo-bts-sysmo/sysmo_l1_if.c:287
#14 0x00016f60 in l1if_fd_cb (ofd=0x16b888, what=1) at osmo-bts-sysmo/sysmo_l1_hw.c:118
#15 0xb6eabe10 in ?? () from /usr/lib/libosmocore.so.17
</pre>
<p>Limited lead up log in the hopes something there is useful.</p>
<pre>
DTBF INFO <0008> tbf_fsm.c:111 TBF(DL-TFI_4)[0x196788]{NEW}: state_chg to ASSIGN [160/1845]
DTBF INFO <0008> tbf_dl_ass_fsm.c:249 DL_ASS_TBF(UL-TFI_14)[0x1c0d60]{SEND_ASS}: Received Event CREATE_RLCMAC_MSG
DRLCMAC ERROR <0002> pdch_ul_controller.c:159 PDCH(bts=0,trx=0,ts=7) FN=1502345 Failed allocating POLL, all RRBP values are already reserved!
DTBF INFO <0008> tbf_dl_ass_fsm.c:249 DL_ASS_TBF(UL-TFI_14)[0x1c0d60]{SEND_ASS}: Received Event CREATE_RLCMAC_MSG
DRLCMAC ERROR <0002> pdch_ul_controller.c:159 PDCH(bts=0,trx=0,ts=7) FN=1502345 Failed allocating POLL, all RRBP values are already reserved!
DTBF INFO <0008> tbf_dl_ass_fsm.c:249 DL_ASS_TBF(UL-TFI_14)[0x1c0d60]{SEND_ASS}: Received Event CREATE_RLCMAC_MSG
DRLCMAC ERROR <0002> pdch_ul_controller.c:159 PDCH(bts=0,trx=0,ts=7) FN=1502345 Failed allocating POLL, all RRBP values are already reserved!
DTBF INFO <0008> tbf_ul.cpp:119 MS(TLLI=0xd3b3f9b1, IMSI=, TA=4, 12/12, UL) Allocating UL TBF
DTBF INFO <0008> ../../git/src/fsm.c:461 TBF[0x1c7518]{NEW}: Allocated
DTBF INFO <0008> ../../git/src/fsm.c:461 UL_ASS_TBF[0x1c7600]{NONE}: Allocated
DTBF INFO <0008> ../../git/src/fsm.c:461 DL_ASS_TBF[0x1c76f0]{NONE}: Allocated
DTBFUL INFO <000a> ../../git/src/fsm.c:461 UL_ACK_TBF[0x1c77e0]{NONE}: Allocated
DRLCMAC NOTICE <0002> gprs_rlcmac_ts_alloc.cpp:775 No USF available
DRLCMAC NOTICE <0002> gprs_rlcmac_ts_alloc.cpp:394 [UL] algo A <multi> (suggested TRX: 0): failed to allocate a TS, no USF available
DTBF NOTICE <0008> tbf.cpp:667 TBF(TFI=0 TLLI=0xd3b3f9b1 DIR=UL STATE=NEW EGPRS) Timeslot Allocation failed: trx = 0, single_slot = 0
DTBFUL INFO <000a> ../../git/src/fsm.c:573 UL_ACK_TBF[0x1c77e0]{NONE}: Deallocated
DTBF INFO <0008> ../../git/src/fsm.c:573 TBF[0x1c7518]{NEW}: Deallocated
DTBF INFO <0008> ../../git/src/fsm.c:573 UL_ASS_TBF[0x1c7600]{NONE}: Deallocated
DTBF INFO <0008> ../../git/src/fsm.c:573 DL_ASS_TBF[0x1c76f0]{NONE}: Deallocated
DTBF NOTICE <0008> tbf_ul.cpp:161 MS(TLLI=0xd3b3f9b1, IMSI=, TA=4, 12/12, UL) No PDCH resource
DTBF INFO <0008> ../../git/src/fsm.c:461 TBF[0x1c7518]{NEW}: Allocated
DTBF INFO <0008> ../../git/src/fsm.c:461 UL_ASS_TBF[0x1c7600]{NONE}: Allocated
DTBF INFO <0008> ../../git/src/fsm.c:461 DL_ASS_TBF[0x1c76f0]{NONE}: Allocated
DTBFUL INFO <000a> ../../git/src/fsm.c:461 UL_ACK_TBF[0x1c77e0]{NONE}: Allocated
DTBF INFO <0008> tbf_ul.cpp:224 TBF[0x1c7518]{NEW}: Received Event ASSIGN_ADD_PACCH
DTBF INFO <0008> tbf_fsm.c:89 TBF(TFI=0 TLLI=0xd3b3f9b1 DIR=UL STATE=NEW) set ass. type PACCH [prev CCCH:0, PACCH:0]
DTBF INFO <0008> tbf_fsm.c:111 TBF[0x1c7518]{NEW}: state_chg to ASSIGN
DTBF INFO <0008> tbf_ul.cpp:225 UL_ASS_TBF[0x1c7600]{NONE}: Received Event SCHED_ASS_REJ
DTBF INFO <0008> tbf_ul_ass_fsm.c:171 UL_ASS_TBF[0x1c7600]{NONE}: state_chg to SEND_ASS_REJ
DTBF INFO <0008> tbf_dl_ass_fsm.c:249 DL_ASS_TBF(UL-TFI_14)[0x1c0d60]{SEND_ASS}: Received Event CREATE_RLCMAC_MSG
DTBF INFO <0008> tbf_dl_ass_fsm.c:102 TBF(TFI=4 TLLI=0xa0e7aec7 DIR=DL STATE=ASSIGN EGPRS) start Packet Downlink Assignment (PACCH)
DTBFDL INFO <0009> tbf_dl_ass_fsm.c:120 TBF(TFI=14 TLLI=0xa0e7aec7 DIR=UL STATE=FINISHED EGPRS) Scheduled DL Assignment polling on PACCH (FN=1502375, TS=7)
DTBF INFO <0008> tbf_dl_ass_fsm.c:157 DL_ASS_TBF(UL-TFI_14)[0x1c0d60]{SEND_ASS}: state_chg to WAIT_ACK
DRLCMAC NOTICE <0002> pdch_ul_controller.c:330 PDCH(bts=0,trx=0,ts=7) Timeout for registered POLL (FN=1502340, reason=UL_ASS): TBF(TFI=13 TLLI=0x9f682c88 DIR=UL STATE=ASSIGN EGPRS)
DTBF NOTICE <0008> tbf.cpp:550 TBF(TFI=13 TLLI=0x9f682c88 DIR=UL STATE=ASSIGN EGPRS) poll timeout for FN=1502340, TS=7 (curr FN 1502340)
DTBF INFO <0008> tbf.cpp:589 UL_ASS_TBF(UL-TFI_13)[0x1bfe30]{WAIT_ACK}: Received Event ASS_POLL_TIMEOUT [125/1845]
DTBF NOTICE <0008> tbf_ul_ass_fsm.c:236 TBF(TFI=13 TLLI=0x9f682c88 DIR=UL STATE=ASSIGN EGPRS) Timeout for polling PACKET CONTROL ACK for PACKET UPLINK ASSIGNMENT: |Assignment was on PACC
H|No uplink data received yet|
DTBF INFO <0008> tbf_ul_ass_fsm.c:239 UL_ASS_TBF(UL-TFI_13)[0x1bfe30]{WAIT_ACK}: state_chg to SEND_ASS
DTBFUL INFO <000a> tbf_ul_ack_fsm.c:233 UL_ACK_TBF(UL-TFI_14)[0x1c0e00]{SCHED_UL_ACK}: Received Event CREATE_RLCMAC_MSG
DTBFUL INFO <000a> tbf_ul_ack_fsm.c:134 UL_ACK_TBF(UL-TFI_14)[0x1c0e00]{SCHED_UL_ACK}: state_chg to WAIT_ACK
DRLCMAC NOTICE <0002> pdch_ul_controller.c:330 PDCH(bts=0,trx=0,ts=7) Timeout for registered POLL (FN=1502345, reason=UL_ASS): TBF(TFI=18 TLLI=0xd7144dff DIR=UL STATE=ASSIGN EGPRS)
DTBF NOTICE <0008> tbf.cpp:550 TBF(TFI=18 TLLI=0xd7144dff DIR=UL STATE=ASSIGN EGPRS) poll timeout for FN=1502345, TS=7 (curr FN 1502345)
DTBF INFO <0008> tbf.cpp:589 UL_ASS_TBF(UL-TFI_18)[0x1c5770]{WAIT_ACK}: Received Event ASS_POLL_TIMEOUT
DTBF NOTICE <0008> tbf_ul_ass_fsm.c:236 TBF(TFI=18 TLLI=0xd7144dff DIR=UL STATE=ASSIGN EGPRS) Timeout for polling PACKET CONTROL ACK for PACKET UPLINK ASSIGNMENT: |Assignment was on PACC
H|No uplink data received yet|
DTBF INFO <0008> tbf_ul_ass_fsm.c:239 UL_ASS_TBF(UL-TFI_18)[0x1c5770]{WAIT_ACK}: state_chg to SEND_ASS
DTBF INFO <0008> tbf_ul_ass_fsm.c:337 UL_ASS_TBF(UL-TFI_15)[0x1c1898]{SEND_ASS}: Received Event CREATE_RLCMAC_MSG
DTBFUL INFO <000a> tbf_ul_ass_fsm.c:113 TBF(TFI=15 TLLI=0xbddbc2d8 DIR=UL STATE=ASSIGN EGPRS) start Packet Uplink Assignment (PACCH)
DTBFUL INFO <000a> tbf_ul_ass_fsm.c:132 TBF(TFI=15 TLLI=0xbddbc2d8 DIR=UL STATE=ASSIGN EGPRS) Scheduled UL Assignment polling on PACCH (FN=1502384, TS=7)
DTBF INFO <0008> tbf_ul_ass_fsm.c:192 UL_ASS_TBF(UL-TFI_15)[0x1c1898]{SEND_ASS}: state_chg to WAIT_ACK
DRLCMAC NOTICE <0002> pdch_ul_controller.c:330 PDCH(bts=0,trx=0,ts=7) Timeout for registered POLL (FN=1502349, reason=UL_ASS): TBF(TFI=16 TLLI=0xfcb4c5a6 DIR=UL STATE=ASSIGN EGPRS)
DTBF NOTICE <0008> tbf.cpp:550 TBF(TFI=16 TLLI=0xfcb4c5a6 DIR=UL STATE=ASSIGN EGPRS) poll timeout for FN=1502349, TS=7 (curr FN 1502349)
DTBF INFO <0008> tbf.cpp:589 UL_ASS_TBF(UL-TFI_16)[0x19a768]{WAIT_ACK}: Received Event ASS_POLL_TIMEOUT
DTBF NOTICE <0008> tbf_ul_ass_fsm.c:236 TBF(TFI=16 TLLI=0xfcb4c5a6 DIR=UL STATE=ASSIGN EGPRS) Timeout for polling PACKET CONTROL ACK for PACKET UPLINK ASSIGNMENT: |Assignment was on PACC
H|No uplink data received yet|
DTBF INFO <0008> tbf_ul_ass_fsm.c:239 UL_ASS_TBF(UL-TFI_16)[0x19a768]{WAIT_ACK}: state_chg to SEND_ASS
DTBF INFO <0008> tbf_ul_ass_fsm.c:337 UL_ASS_TBF(UL-TFI_13)[0x1bfe30]{SEND_ASS}: Received Event CREATE_RLCMAC_MSG
DRLCMAC ERROR <0002> pdch_ul_controller.c:159 PDCH(bts=0,trx=0,ts=7) FN=1502362 Failed allocating POLL, all RRBP values are already reserved!
DRLCMAC NOTICE <0002> pdch_ul_controller.c:330 PDCH(bts=0,trx=0,ts=5) Timeout for registered POLL (FN=1502353, reason=DL_ASS): TBF(TFI=2 TLLI=0xfcb4c5a6 DIR=DL STATE=ASSIGN EGPRS)
DTBF NOTICE <0008> tbf.cpp:550 TBF(TFI=2 TLLI=0xfcb4c5a6 DIR=DL STATE=ASSIGN EGPRS) poll timeout for FN=1502353, TS=5 (curr FN 1502353)
DTBF INFO <0008> tbf.cpp:608 DL_ASS_TBF(DL-TFI_2)[0x199e40]{WAIT_ACK}: Received Event ASS_POLL_TIMEOUT
DTBF NOTICE <0008> tbf_dl_ass_fsm.c:175 TBF(TFI=2 TLLI=0xfcb4c5a6 DIR=DL STATE=ASSIGN EGPRS) Timeout for polling PACKET CONTROL ACK for PACKET DOWNLINK ASSIGNMENT: |Assignment was on PAC
CH|No downlink ACK received yet|
DTBF INFO <0008> tbf_dl_ass_fsm.c:177 DL_ASS_TBF(DL-TFI_2)[0x199e40]{WAIT_ACK}: state_chg to SEND_ASS
DRLCMAC NOTICE <0002> pdch_ul_controller.c:337 PDCH(bts=0,trx=0,ts=7) Timeout for registered SBA (FN=1502353, TA=4)
DTBF INFO <0008> tbf_dl_ass_fsm.c:249 DL_ASS_TBF(DL-TFI_2)[0x199e40]{SEND_ASS}: Received Event CREATE_RLCMAC_MSG
DTBF INFO <0008> tbf_dl_ass_fsm.c:102 TBF(TFI=2 TLLI=0xfcb4c5a6 DIR=DL STATE=ASSIGN EGPRS) start Packet Downlink Assignment (PACCH)
DTBFDL INFO <0009> tbf_dl_ass_fsm.c:120 TBF(TFI=2 TLLI=0xfcb4c5a6 DIR=DL STATE=ASSIGN EGPRS) Scheduled DL Assignment polling on PACCH (FN=1502379, TS=5)
DTBF INFO <0008> tbf_dl_ass_fsm.c:157 DL_ASS_TBF(DL-TFI_2)[0x199e40]{SEND_ASS}: state_chg to WAIT_ACK
DTBF INFO <0008> tbf_ul_ass_fsm.c:337 UL_ASS_TBF(UL-TFI_13)[0x1bfe30]{SEND_ASS}: Received Event CREATE_RLCMAC_MSG
DTBFUL INFO <000a> tbf_ul_ass_fsm.c:113 TBF(TFI=0 TLLI=0x9f682c88 DIR=UL STATE=ASSIGN) start Packet Uplink Assignment (PACCH)
Assert failed pdch != NULL encoding.cpp:561
</pre>
<p><a class="external" href="https://www.rhizomatica.org/files/OS_5293-1.zip">https://www.rhizomatica.org/files/OS_5293-1.zip</a></p> OsmoPCU - Bug #5293: Assert failed pdch != NULL encoding.cpp:561https://osmocom.org/issues/5293?journal_id=229282021-11-06T04:49:27Zkeith
<ul><li><strong>Related to</strong> <i><a class="issue tracker-1 status-3 priority-2 priority-default closed" href="/issues/5264">Bug #5264</a>: ASSERT in encoding.cpp:561</i> added</li></ul> OsmoPCU - Bug #5293: Assert failed pdch != NULL encoding.cpp:561https://osmocom.org/issues/5293?journal_id=229292021-11-06T04:58:42Zkeith
<ul></ul><p><a class="user active" href="https://osmocom.org/users/30187">pespin</a> just looking at your notes on <a class="issue tracker-1 status-3 priority-2 priority-default closed" title="Bug: ASSERT in encoding.cpp:561 (Resolved)" href="https://osmocom.org/issues/5264">#5264</a> - I imagine it's very likely to do with dyn TS. Another day, I'll see if I can force it by configuring a BTS with just one dyn TS and then force that TS to TCH/F while there are TBFs active.</p> OsmoPCU - Bug #5293: Assert failed pdch != NULL encoding.cpp:561https://osmocom.org/issues/5293?journal_id=229302021-11-06T09:01:57Zlaforge
<ul><li><strong>Assignee</strong> set to <i>pespin</i></li><li><strong>Priority</strong> changed from <i>Normal</i> to <i>High</i></li></ul><p><a class="user active" href="https://osmocom.org/users/30187">pespin</a> has been tracking down PCU related segfaults [all?] last week so assigning this to him. It's unfortunate that we are seeing those stability issues in recent weeks, and we need to get those resolved ASAP.</p> OsmoPCU - Bug #5293: Assert failed pdch != NULL encoding.cpp:561https://osmocom.org/issues/5293?journal_id=229342021-11-07T23:02:45Zkeith
<ul></ul><p>keith wrote in <a href="#note-4">#note-4</a>:</p>
<blockquote>
<p>Another day, I'll see if I can force it by configuring a BTS with just one dyn TS and then force that TS to TCH/F while there are TBFs active.</p>
</blockquote>
<p>no luck with that. I cannot force the crash this way. Probably I need lots more activity than just one phone.</p> OsmoPCU - Bug #5293: Assert failed pdch != NULL encoding.cpp:561https://osmocom.org/issues/5293?journal_id=229422021-11-08T13:47:27Zpespin
<ul></ul><p>Hi <a class="user active" href="https://osmocom.org/users/4282">keith</a> , I submitted a bunch of patches whcih may help with fixing/improving the situation:<br />remote: <a class="external" href="https://gerrit.osmocom.org/c/osmo-pcu/+/26151">https://gerrit.osmocom.org/c/osmo-pcu/+/26151</a> tbf: Increase log level of line about unable to allocate poll for TBF<br />remote: <a class="external" href="https://gerrit.osmocom.org/c/osmo-pcu/+/26152">https://gerrit.osmocom.org/c/osmo-pcu/+/26152</a> pdch: Improve log line and increase log level<br />remote: <a class="external" href="https://gerrit.osmocom.org/c/osmo-pcu/+/26154">https://gerrit.osmocom.org/c/osmo-pcu/+/26154</a> tbf_ul: Set first_(common_)ts in handle_tbf_reject [NEW]<br />remote: <a class="external" href="https://gerrit.osmocom.org/c/osmo-pcu/+/26155">https://gerrit.osmocom.org/c/osmo-pcu/+/26155</a> tbf: Set m_created_ts in constructor [NEW]<br />remote: <a class="external" href="https://gerrit.osmocom.org/c/osmo-pcu/+/26156">https://gerrit.osmocom.org/c/osmo-pcu/+/26156</a> tbf: Mark initial first_(common_)ts with special value [NEW]<br />remote: <a class="external" href="https://gerrit.osmocom.org/c/osmo-pcu/+/26157">https://gerrit.osmocom.org/c/osmo-pcu/+/26157</a> tbf: Set tfi to initial special value [NEW]<br />remote: <a class="external" href="https://gerrit.osmocom.org/c/osmo-pcu/+/26158">https://gerrit.osmocom.org/c/osmo-pcu/+/26158</a> tbf_ul: Update FSM names for dummy reject TBFs [NEW]</p>
<p>Please if you still see the crash keep posting logs as you did, if possible with far more lines and more verbosity (INFO), since I usually require to understand the full life cycle of the TBF.</p>
<p>Regarding the debug info: Since osmo-pcu is partly C++, remember CFLAGS alone won't work. Better pass CXXFLAGS too.</p> OsmoPCU - Bug #5293: Assert failed pdch != NULL encoding.cpp:561https://osmocom.org/issues/5293?journal_id=229492021-11-08T18:51:31Zkeith
<ul></ul><p>Thanks Pau, I will build and install that now. (with CXXFLAGS)</p>
<p>BTW, It occurs to me that I should let you know that on most systems where I am testing this pcu, It is running alongside the osmo-bts-sysmo binary from the "latest" builds, although some have a binary I have built which is (at least) later than "latest" but I haven't been including this information. I'm not sure if there have been changes in osmo-bts that relate to dyn chans or pcu communication that might be relevant. It's been some weeks since I tested it against a "master" osmo-bts-sysmo</p>
<p>Also, just to be complete, osmo-bsc and sgsn etc are "latest", not master/nightly.</p> OsmoPCU - Bug #5293: Assert failed pdch != NULL encoding.cpp:561https://osmocom.org/issues/5293?journal_id=229502021-11-08T19:39:53Zkeith
<ul><li><strong>File</strong> <a href="/attachments/4740">pcu.log.gz</a> <a class="icon-only icon-download" title="Download" href="/attachments/download/4740/pcu.log.gz">pcu.log.gz</a> added</li></ul><p>Attaching complete log from start to ASSERT.</p>
<p><strong>OsmoPCU version 0.9.0.259-ef8a</strong></p> OsmoPCU - Bug #5293: Assert failed pdch != NULL encoding.cpp:561https://osmocom.org/issues/5293?journal_id=229542021-11-09T06:43:38Zkeith
<ul></ul><p>Here is another log and core for this one: <a class="external" href="https://www.rhizomatica.org/files/5293-2.zip">https://www.rhizomatica.org/files/5293-2.zip</a></p>
<p>EDIT: sorry, just noticed the log ends before the crash due to out of disk space again :(</p> OsmoPCU - Bug #5293: Assert failed pdch != NULL encoding.cpp:561https://osmocom.org/issues/5293?journal_id=229662021-11-10T05:12:36Zkeith
<ul><li><strong>File</strong> <a href="/attachments/4741">tmux-buffer.txt</a> <a class="icon-only icon-download" title="Download" href="/attachments/download/4741/tmux-buffer.txt">tmux-buffer.txt</a> added</li></ul><p>Caught one of these fairly soon after startup</p> OsmoPCU - Bug #5293: Assert failed pdch != NULL encoding.cpp:561https://osmocom.org/issues/5293?journal_id=229672021-11-10T05:16:26Zkeith
<ul></ul><pre>
(gdb) p *tbf
$3 = {_vptr.gprs_rlcmac_tbf = 0xb5804 <vtable for gprs_rlcmac_ul_tbf+8>, direction = GPRS_RLCMAC_UL_TBF, trx = 0x1635ac, first_ts = 7 '\a', first_common_ts = 7 '\a',
control_ts = 7 '\a', pdch = {0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}, m_llc = {frame = 'B' <repeats 1543 times>, m_index = 0, m_length = 0}, m_rlc = {m_blocks = {{
block = '\000' <repeats 73 times>, len = 0 '\000', block_info = {data_len = 0, bsn = 0, ti = 0, e = 0, cv = 0, pi = 0, spb = 0}, cs_current_trans = UNKNOWN, cs_last = UNKNOWN,
cs_init = UNKNOWN, next_ps = EGPRS_PS_1, spb_status = {block_status_ul = EGPRS_RESEG_DEFAULT, block_status_dl = EGPRS_RESEG_DL_DEFAULT}} <repeats 1024 times>}}, fT = 0,
num_fT_exp = 0, meas = {rssi_tv = {tv_sec = 0, tv_nsec = 0}, rssi_sum = 0, rssi_num = 0}, upgrade_to_multislot = false, bts = 0x163580, m_tfi = 255 '\377', m_created_ts = 1636520839,
m_ctrs = 0x1958c8, state_fsm = {fi = 0x197278, tbf = 0x258230, state_flags = 2, T_release = 0}, ul_ass_fsm = {fi = 0x1948a0, tbf = 0x258230}, dl_ass_fsm = {fi = 0x193840,
tbf = 0x258230}, m_ms_list = {list = {next = 0x0, prev = 0x0}, entry = 0x258230}, m_trx_list = {list = {next = 0x19236c, prev = 0x215fbc}, entry = 0x258230}, m_ms = 0x1710f8,
m_egprs_enabled = false, Tarr = {{node = {rb_parent_color = 0, rb_right = 0x0, rb_left = 0x0}, list = {next = 0x0, prev = 0x0}, timeout = {tv_sec = 0, tv_usec = 0}, active = 0,
cb = 0x0, data = 0x0}, {node = {rb_parent_color = 0, rb_right = 0x0, rb_left = 0x0}, list = {next = 0x0, prev = 0x0}, timeout = {tv_sec = 0, tv_usec = 0}, active = 0, cb = 0x0,
data = 0x0}}, Narr = "\000\000", m_name_buf = "TBF(TFI=-1 TLLI=0x9bc4efa8 DIR=UL STATE=ASSIGN)\000S)\000PRS)\000\000\000\000"}
</pre> OsmoPCU - Bug #5293: Assert failed pdch != NULL encoding.cpp:561https://osmocom.org/issues/5293?journal_id=229752021-11-10T16:08:24Zpespin
<ul></ul><p>In tmux-buffer.txt I'm seeing the same MS (TLII=0x9bc4efa8, the one making crash the PCU) several times creating a TBF through RACH + Pkt Res REq (two phase access) while the previous UL TBF is still ongoing trying to assign the 2nd phase tbf over PACCH. At the moment I'm seeing 3 concurrent UL TBFs.</p>
<p>I believe this patch should improve the situation and avoid resources being reserved for longer time than needed:<br /><a class="external" href="https://gerrit.osmocom.org/c/osmo-pcu/+/26198">https://gerrit.osmocom.org/c/osmo-pcu/+/26198</a> pdch: Drop previous UL TBF from MS who sent PktResReq through SBA</p> OsmoPCU - Bug #5293: Assert failed pdch != NULL encoding.cpp:561https://osmocom.org/issues/5293?journal_id=229772021-11-10T17:25:00Zpespin
<ul></ul><p>Ok, thanks to my last patches improving logging I now understand what's happening.</p>
<p>First a UL TBF is created for the MS (TFI=0):</p>
<pre>
Wed Nov 10 05:07:18 2021 DCSN1 INFO gsm_rlcmac.c:5394 csnStreamDecoder (type: Pkt Resource Req (5)):
Wed Nov 10 05:07:18 2021 DRLCMAC INFO gprs_ms.c:533 Modifying MS object, TLLI = 0x9bc4efa8, TA 4 -> 5
Wed Nov 10 05:07:18 2021 DTBF INFO tbf_ul.cpp:119 MS(TLLI=0x9bc4efa8, IMSI=, TA=5, 12/12, UL) Allocating UL TBF
Wed Nov 10 05:07:18 2021 DTBF INFO ../../git/src/fsm.c:461 TBF[0x170f70]{NEW}: Allocated
Wed Nov 10 05:07:18 2021 DTBF INFO ../../git/src/fsm.c:461 UL_ASS_TBF[0x1b7fb0]{NONE}: Allocated
Wed Nov 10 05:07:18 2021 DTBF INFO ../../git/src/fsm.c:461 DL_ASS_TBF[0x2796f0]{NONE}: Allocated
Wed Nov 10 05:07:18 2021 DTBFUL INFO ../../git/src/fsm.c:461 UL_ACK_TBF[0x16cac8]{NONE}: Allocated
Wed Nov 10 05:07:18 2021 DRLCMAC INFO gprs_rlcmac_ts_alloc.cpp:947 [UL] algo B <multi> (suggested TRX: 0): using 1 slots
Wed Nov 10 05:07:18 2021 DRLCMAC INFO pdch.cpp:1159 PDCH(bts=0,trx=0,ts=5) Attaching TBF(TFI=0 TLLI=0x9bc4efa8 DIR=UL STATE=NEW EGPRS), 6 TBFs, USFs = 77, TFIs = 000002c7.
Wed Nov 10 05:07:18 2021 DTBF INFO tbf.cpp:345 TBF(TFI=0 TLLI=0x9bc4efa8 DIR=UL STATE=NEW EGPRS) Setting Control TS 5
Wed Nov 10 05:07:18 2021 DTBF INFO tbf.cpp:680 TBF(TFI=0 TLLI=0x9bc4efa8 DIR=UL STATE=NEW EGPRS) Allocated: trx = 0, ul_slots = 20, dl_slots = 00
Wed Nov 10 05:07:18 2021 DRLCMAC INFO gprs_ms.c:301 MS(TLLI=0x9bc4efa8, IMSI=, TA=5, 12/12, UL) Attaching UL TBF: TBF(TFI=0 TLLI=0x9bc4efa8 DIR=UL STATE=NEW EGPRS)
Wed Nov 10 05:07:18 2021 DTBFUL INFO tbf_ul.cpp:750 TBF(TFI=0 TLLI=0x9bc4efa8 DIR=UL STATE=NEW EGPRS) setting EGPRS UL window size to 64, base(64) slots(1) ws_pdch(0)
Wed Nov 10 05:07:18 2021 DRLCMAC INFO rlc.cpp:249 ws(64)
Wed Nov 10 05:07:18 2021 DTBF INFO tbf_ul.cpp:172 TBF(UL-TFI_0)[0x170f70]{NEW}: Received Event ASSIGN_ADD_PACCH
Wed Nov 10 05:07:18 2021 DTBF INFO tbf_fsm.c:89 TBF(TFI=0 TLLI=0x9bc4efa8 DIR=UL STATE=NEW EGPRS) set ass. type PACCH [prev CCCH:0, PACCH:0]
Wed Nov 10 05:07:18 2021 DTBF INFO tbf_fsm.c:111 TBF(UL-TFI_0)[0x170f70]{NEW}: state_chg to ASSIGN
// ul_tbf->control_ts = 7;
Wed Nov 10 05:07:18 2021 DTBF INFO pdch.cpp:759 UL_ASS_TBF(UL-TFI_0)[0x1b7fb0]{NONE}: Received Event SCHED_ASS
Wed Nov 10 05:07:18 2021 DTBF INFO tbf_ul_ass_fsm.c:168 UL_ASS_TBF(UL-TFI_0)[0x1b7fb0]{NONE}: state_chg to SEND_ASS
Wed Nov 10 05:07:18 2021 DTBF INFO tbf_ul_ass_fsm.c:337 UL_ASS_TBF(UL-TFI_0)[0x1b7fb0]{SEND_ASS}: Received Event CREATE_RLCMAC_MSG
Wed Nov 10 05:07:18 2021 DTBFUL INFO tbf_ul_ass_fsm.c:113 TBF(TFI=0 TLLI=0x9bc4efa8 DIR=UL STATE=ASSIGN EGPRS) start Packet Uplink Assignment (PACCH)
Wed Nov 10 05:07:18 2021 DCSN1 INFO gsm_rlcmac.c:5878 csnStreamEncoder (type: Pkt UL ASS (10)):
Wed Nov 10 05:07:18 2021 DTBFUL INFO tbf_ul_ass_fsm.c:132 TBF(TFI=0 TLLI=0x9bc4efa8 DIR=UL STATE=ASSIGN EGPRS) Scheduled UL Assignment polling on PACCH (FN=1787989, TS=7)
Wed Nov 10 05:07:18 2021 DTBF INFO tbf_ul_ass_fsm.c:192 UL_ASS_TBF(UL-TFI_0)[0x1b7fb0]{SEND_ASS}: state_chg to WAIT_ACK
</pre>
<p>Then it goes on "forever" (until MAX_31.. triggers) in ASSIGN state with UL_ASS_TBF trying to send a Pkt Ul Ass over PACCH.<br />Now, this is how it works (tbf_ul_ass_fsm.c create_packet_ul_assign()):<br /><pre>
struct msgb *create_packet_ul_assign(const struct tbf_ul_ass_fsm_ctx *ctx,
const struct tbf_ul_ass_ev_create_rlcmac_msg_ctx *d) {
// Curerent tbf owner of the FSM is in ctx->tbf, aka TFI=0 above mentioned
....
rc = tbf_check_polling(ctx->tbf, d->fn, d->ts, &new_poll_fn, &rrbp);
if (rc < 0)
return NULL;
new_tbf = ms_ul_tbf(ms); // HERE IT TAKES THE NEWEST ALLOCATED UL TBF IN THE MS, WHICH HAPPENS TO BE ITSELF IN THIS CASE
if (!new_tbf) {
LOGPTBF(ctx->tbf, LOGL_ERROR,
"We have a schedule for uplink assignment, but there is no uplink TBF\n");
tbf_ul_ass_fsm_state_chg(ctx->fi, TBF_UL_ASS_NONE);
return NULL;
}
</pre></p>
<p>It goes one sending Pkt Ul Ass but itis never answered.</p>
<p>Then, the MS tries to reconnect against through CCCH RACH then SBA with Pkt resoure request (two phase access), but there's no more USF, so it fails, and a dummy TBF is created to send the PktResourceReject:<br /><pre>
Wed Nov 10 05:07:19 2021 DCSN1 INFO gsm_rlcmac.c:5394 csnStreamDecoder (type: Pkt Resource Req (5)):
Wed Nov 10 05:07:19 2021 DRLCMAC INFO gprs_ms.c:533 Modifying MS object, TLLI = 0x9bc4efa8, TA 0 -> 4
Wed Nov 10 05:07:19 2021 DTBF INFO tbf_ul.cpp:119 MS(TLLI=0x9bc4efa8, IMSI=, TA=4, 12/12, UL) Allocating UL TBF
Wed Nov 10 05:07:19 2021 DTBF INFO ../../git/src/fsm.c:461 TBF[0x1948a0]{NEW}: Allocated
Wed Nov 10 05:07:19 2021 DTBF INFO ../../git/src/fsm.c:461 UL_ASS_TBF[0x193840]{NONE}: Allocated
Wed Nov 10 05:07:19 2021 DTBF INFO ../../git/src/fsm.c:461 DL_ASS_TBF[0x1d4158]{NONE}: Allocated
Wed Nov 10 05:07:19 2021 DTBFUL INFO ../../git/src/fsm.c:461 UL_ACK_TBF[0x197278]{NONE}: Allocated
Wed Nov 10 05:07:19 2021 DRLCMAC NOTICE gprs_rlcmac_ts_alloc.cpp:775 No USF available
Wed Nov 10 05:07:19 2021 DRLCMAC NOTICE gprs_rlcmac_ts_alloc.cpp:394 [UL] algo A <multi> (suggested TRX: 0): failed to allocate a TS, no USF available
Wed Nov 10 05:07:19 2021 DTBF NOTICE tbf.cpp:668 TBF(TFI=-1 TLLI=0x9bc4efa8 DIR=UL STATE=NEW EGPRS) Timeslot Allocation failed: trx = 0, single_slot = 0
Wed Nov 10 05:07:19 2021 DTBFUL INFO ../../git/src/fsm.c:573 UL_ACK_TBF[0x197278]{NONE}: Deallocated
Wed Nov 10 05:07:19 2021 DTBF INFO ../../git/src/fsm.c:573 TBF[0x1948a0]{NEW}: Deallocated
Wed Nov 10 05:07:19 2021 DTBF INFO ../../git/src/fsm.c:573 UL_ASS_TBF[0x193840]{NONE}: Deallocated
Wed Nov 10 05:07:19 2021 DTBF INFO ../../git/src/fsm.c:573 DL_ASS_TBF[0x1d4158]{NONE}: Deallocated
Wed Nov 10 05:07:19 2021 DTBF NOTICE tbf_ul.cpp:166 MS(TLLI=0x9bc4efa8, IMSI=, TA=4, 12/12, UL) No PDCH resource
Wed Nov 10 05:07:19 2021 DTBF INFO ../../git/src/fsm.c:461 TBF[0x197278]{NEW}: Allocated
Wed Nov 10 05:07:19 2021 DTBF INFO ../../git/src/fsm.c:461 UL_ASS_TBF[0x1948a0]{NONE}: Allocated
Wed Nov 10 05:07:19 2021 DTBF INFO ../../git/src/fsm.c:461 DL_ASS_TBF[0x193840]{NONE}: Allocated
Wed Nov 10 05:07:19 2021 DTBFUL INFO ../../git/src/fsm.c:461 UL_ACK_TBF[0x1d4158]{NONE}: Allocated
Wed Nov 10 05:07:19 2021 DTBF INFO tbf.cpp:345 TBF(TFI=-1 TLLI=0x9bc4efa8 DIR=UL STATE=NEW) Setting Control TS 7
Wed Nov 10 05:07:19 2021 DRLCMAC INFO gprs_ms.c:301 MS(TLLI=0x9bc4efa8, IMSI=, TA=4, 12/12, UL) Attaching UL TBF: TBF(TFI=-1 TLLI=0x9bc4efa8 DIR=UL STATE=NEW)
Wed Nov 10 05:07:19 2021 DTBF INFO tbf_ul.cpp:235 TBF(UL-TFI_-1)[0x197278]{NEW}: Received Event ASSIGN_ADD_PACCH
Wed Nov 10 05:07:19 2021 DTBF INFO tbf_fsm.c:89 TBF(TFI=-1 TLLI=0x9bc4efa8 DIR=UL STATE=NEW) set ass. type PACCH [prev CCCH:0, PACCH:0]
Wed Nov 10 05:07:19 2021 DTBF INFO tbf_fsm.c:111 TBF(UL-TFI_-1)[0x197278]{NEW}: state_chg to ASSIGN
Wed Nov 10 05:07:19 2021 DTBF INFO tbf_ul.cpp:236 UL_ASS_TBF(UL-TFI_-1)[0x1948a0]{NONE}: Received Event SCHED_ASS_REJ
Wed Nov 10 05:07:19 2021 DTBF INFO tbf_ul_ass_fsm.c:171 UL_ASS_TBF(UL-TFI_-1)[0x1948a0]{NONE}: state_chg to SEND_ASS_REJ
</pre></p>
<p>So now, the "newest" TBF in GprsMS is the dummy TBF. Now, see what happens: TFI=0 is still ongoing and trying to send a PktAssUl, so scheduler schedules it:<br /><pre>
Wed Nov 10 05:07:19 2021 DTBF INFO tbf_ul_ass_fsm.c:337 UL_ASS_TBF(UL-TFI_0)[0x1b7fb0]{SEND_ASS}: Received Event CREATE_RLCMAC_MSG // TFI=0 IS SELECTED, IT GOES THROUGH PATH MENTIONED ABOVE
Wed Nov 10 05:07:19 2021 DTBFUL INFO tbf_ul_ass_fsm.c:113 TBF(TFI=-1 TLLI=0x9bc4efa8 DIR=UL STATE=ASSIGN) start Packet Uplink Assignment (PACCH) //TFI=-1 (dummy TBF) TAKEN BECAUSE IT'S THE NEWEST IN MS, AKA ms_ul_tbf(ms).
Assert failed pdch != NULL encoding.cpp:561 // TFI=0 TRIES TO SEND A PKT UL ASS FOR TFI=-1 (dummy tbf), WHICH IS WRONG!!!!
backtrace() returned 0 addresses
</pre><br />TFI=-1 has no attached TBF, hence calling "gen_freq_params(fp, tbf);" on it will crash, due to:<br /><pre>
pdch = tbf->pdch[tbf->first_ts]; // DUMMY TBFs HAVE NO PDCH ATTACHED; HENCE ALL IN pdch[] ARE NULL:
// first_ts = 7 '\a', first_common_ts = 7 '\a', control_ts = 7 '\a', pdch = {0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}
</pre></p> OsmoPCU - Bug #5293: Assert failed pdch != NULL encoding.cpp:561https://osmocom.org/issues/5293?journal_id=229782021-11-10T17:27:21Zpespin
<ul><li><strong>Status</strong> changed from <i>New</i> to <i>Feedback</i></li><li><strong>Assignee</strong> changed from <i>pespin</i> to <i>keith</i></li><li><strong>% Done</strong> changed from <i>0</i> to <i>90</i></li></ul><p>I believe the previous patch I submitted before should prevent this sort of issues from happening, since the previous TBF should be freed upon the newest one being created. As a result, the pending PktUlAss TFI=0 cannot be scheduler to trigger TFI=-1 becuase the former simply won't exist at this point in time.<br /><a class="external" href="https://gerrit.osmocom.org/c/osmo-pcu/+/26198">https://gerrit.osmocom.org/c/osmo-pcu/+/26198</a> pdch: Drop previous UL TBF from MS who sent PktResReq through SBA</p>
<p>At some point in the future I'll try to get rid of those dummt TBFs to send PktAssReject and use a different struct to avoid this kind of issues.</p>
<p>Please <a class="user active" href="https://osmocom.org/users/4282">keith</a> , give it a try ASAP and provide some feedback.</p> OsmoPCU - Bug #5293: Assert failed pdch != NULL encoding.cpp:561https://osmocom.org/issues/5293?journal_id=229802021-11-10T20:31:25Zkeith
<ul></ul><p>Hi <a class="user active" href="https://osmocom.org/users/30187">pespin</a></p>
<p>What I'm seeing now is this log repeating rapidly (quite some entries per second):</p>
<pre>
DTBF <0008> tbf_dl_ass_fsm.c:75 TBF(TFI=5 TLLI=0x813f06e8 DIR=UL STATE=FINISHED) We have a schedule for downlink assignment, but there is no downlink TBF
DTBF <0008> tbf_dl_ass_fsm.c:76 DL_ASS_TBF(UL-TFI_5)[0x215530]{SEND_ASS}: transition to state NONE not permitted!
</pre> OsmoPCU - Bug #5293: Assert failed pdch != NULL encoding.cpp:561https://osmocom.org/issues/5293?journal_id=229812021-11-10T20:32:53Zkeith
<ul><li><strong>File</strong> <a href="/attachments/4742">c_log.txt</a> <a class="icon-only icon-download" title="Download" href="/attachments/download/4742/c_log.txt">c_log.txt</a> added</li></ul><p>I hit CTRL-S in the terminal to capture this [c_log.txt], of course, then the process exited.</p>
<p>I'll try again and then see if I can stop and inspect the relevant objects in gdb</p> OsmoPCU - Bug #5293: Assert failed pdch != NULL encoding.cpp:561https://osmocom.org/issues/5293?journal_id=229842021-11-11T12:33:51Zpespin
<ul></ul><p>Hi <a class="user active" href="https://osmocom.org/users/4282">keith</a> , it seems you run through a missing transition there. It's fixed here:<br /><a class="external" href="https://gerrit.osmocom.org/c/osmo-pcu/+/26208">https://gerrit.osmocom.org/c/osmo-pcu/+/26208</a> tbf_dl_ass_fsm: Fix missing transition to NONE if DL TBF is nonexistent</p>
<p>Please give it a try when you find some time, I hope we are finally sorting out all big issues.</p> OsmoPCU - Bug #5293: Assert failed pdch != NULL encoding.cpp:561https://osmocom.org/issues/5293?journal_id=230062021-11-12T20:10:37Zkeith
<ul></ul><p>Hi <a class="user active" href="https://osmocom.org/users/30187">pespin</a> <br />I have been running these patches now for about 20 hours with no crash or visible issues.<br />Thanks for all the amazing work!</p>
<p>Here's the stats from running pcu it case it's of interest:</p>
<pre>
OsmoPCU# show bts statistics
BTS0:
BTS Statistics:
TBF DL Allocated : 35897 (1/s 111/m 4444/h 33707/d)
TBF DL Freed : 35881 (2/s 103/m 4442/h 33700/d)
TBF DL Aborted : 1376 (0/s 7/m 230/h 1270/d)
TBF UL Allocated : 179053 (7/s 323/m 22274/h 168867/d)
TBF UL Freed : 179044 (7/s 318/m 22270/h 168866/d)
TBF UL Aborted : 601 (0/s 2/m 117/h 549/d)
TBF Reused : 5488 (0/s 2/m 541/h 5264/d)
TBF Alloc Algo A : 3884 (8/s 28/m 801/h 3463/d)
TBF Alloc Algo B : 226303 (0/s 451/m 27792/h 213443/d)
TBF Alloc Failure (any reason): 20 (0/s 0/m 5/h 18/d)
TBF Alloc Failure (TFIs exhausted): 0 (0/s 0/m 0/h 0/d)
TBF Alloc Failure (USFs exhausted): 21 (0/s 1/m 5/h 18/d)
TBF Alloc Failure (No valid UL/DL slot combination found): 0 (0/s 0/m 0/h 0/d)
TBF Alloc Failure (No slot available): 0 (0/s 0/m 0/h 0/d)
RLC Sent : 7728462 (147/s 16185/m 829092/h 7362349/d)
RLC Resent : 7327766 (112/s 15325/m 770761/h 7004413/d)
RLC Restarted : 4949202 (106/s 10020/m 504572/h 4736469/d)
RLC Stalled : 6078 (0/s 4/m 337/h 5995/d)
RLC Nacked : 265349 (0/s 492/m 28657/h 257089/d)
RLC Final Blk resent : 59082 (0/s 0/m 448/h 58952/d)
RLC Assign Timeout : 252767 (21/s 745/m 50227/h 230328/d)
RLC Assign Failed : 20329 (1/s 84/m 4941/h 18105/d)
RLC Ack Timeout : 96886 (5/s 447/m 15254/h 88914/d)
RLC Ack Failed : 5180 (0/s 40/m 943/h 4597/d)
RLC Release Timeout : 3182 (0/s 28/m 644/h 2759/d)
RLC Late Block : 0 (0/s 0/m 0/h 0/d)
RLC Sent Dummy : 5014810 (18/s 5117/m 366016/h 4823079/d)
RLC Sent Control : 823851 (35/s 1906/m 120738/h 770231/d)
RLC DL Bytes : 844212578 (13239/s 1667010/m 81965692/h 809498721/d)
RLC DL Payload Bytes : 139220810 (3027/s 301231/m 12026319/h 134232684/d)
RLC UL Bytes : 160430752 (1769/s 336534/m 16849703/h 153052680/d)
RLC UL Payload Bytes : 94155418 (254/s 205047/m 9960501/h 89793843/d)
Decode Errors : 413 (0/s 0/m 37/h 387/d)
SBA Allocated : 62736 (1/s 140/m 9842/h 58427/d)
SBA Freed : 62736 (3/s 140/m 9842/h 58427/d)
SBA Timeout : 0 (0/s 0/m 0/h 0/d)
Timedout Frames : 9198 (0/s 40/m 902/h 8746/d)
Dropped Frames : 14868 (0/s 109/m 1752/h 14048/d)
Scheduled Frames : 724437 (7/s 1623/m 73580/h 693506/d)
RLC encapsulated PDUs: 139186498 (3032/s 300873/m 12023192/h 134199527/d)
full PDUs received : 93682751 (549/s 201558/m 9895664/h 89355030/d)
PCH requests sent : 2056 (0/s 0/m 312/h 1907/d)
PCH requests on subscriber already being paged: 1488 (0/s 0/m 228/h 1384/d)
PCH requests timeout : 1954 (0/s 0/m 290/h 1820/d)
RACH requests received: 85125 (2/s 208/m 13021/h 78823/d)
11BIT_RACH requests received: 78268 (1/s 175/m 11457/h 73281/d)
One phase packet access with request for single TS UL: 22387 (1/s 68/m 3179/h 20394/d)
Single block packet request for two phase packet access: 62736 (1/s 140/m 9842/h 58427/d)
RACH Request with unexpected content received: 2 (0/s 0/m 0/h 2/d)
First seg of UL SPB : 16552 (0/s 76/m 2201/h 15671/d)
Second seg of UL SPB : 15852 (0/s 65/m 2087/h 15022/d)
First seg of DL SPB : 71095 (0/s 97/m 7792/h 68001/d)
Second seg of DL SPB : 60800 (0/s 84/m 6428/h 58526/d)
Immediate Assign UL : 85123 (2/s 208/m 13021/h 78821/d)
Immediate Assign UL (one phase packet access): 22387 (1/s 68/m 3179/h 20394/d)
Immediate Assign UL (two phase packet access): 62736 (1/s 140/m 9842/h 58427/d)
First RLC Block (PDU) on the PDTCH from the MS received: 82753 (3/s 206/m 12707/h 76605/d)
Immediate Assign Rej : 2 (0/s 0/m 0/h 2/d)
Immediate Assign DL : 17816 (1/s 54/m 2248/h 16677/d)
Channel Request Desc : 94018 (3/s 113/m 9245/h 90214/d)
Packet UL Assignment : 356698 (26/s 839/m 59593/h 330383/d)
Packet Access Reject : 20 (0/s 0/m 5/h 18/d)
Packet DL Assignment : 61700 (2/s 176/m 8421/h 57805/d)
Packet Cell Change Notification: 672 (0/s 7/m 154/h 613/d)
Packet Cell Change Continue: 4108 (0/s 4/m 732/h 3963/d)
Packet Neighbour Cell Data: 0 (0/s 0/m 0/h 0/d)
UL control Block : 1098968 (29/s 2165/m 119346/h 1047529/d)
UL Assign Timeout : 220721 (21/s 662/m 45382/h 200407/d)
UL Assign Failed : 16602 (1/s 74/m 4372/h 14626/d)
DL Assign Timeout : 32046 (0/s 83/m 4845/h 29921/d)
DL Assign Failed : 3727 (0/s 10/m 569/h 3479/d)
PUAN Poll Timeout : 13367 (0/s 34/m 1463/h 12674/d)
PUAN poll Failed : 2038 (0/s 6/m 224/h 1924/d)
PDAN poll Timeout : 83519 (5/s 413/m 13791/h 76240/d)
PDAN poll Failed : 5180 (0/s 40/m 943/h 4597/d)
CS1 downlink : 4639 (0/s 0/m 1122/h 3843/d)
CS2 downlink : 1568 (0/s 0/m 443/h 1240/d)
CS3 downlink : 26941 (0/s 0/m 7434/h 22543/d)
CS4 downlink : 546071 (0/s 0/m 123106/h 455471/d)
MCS1 downlink : 65828 (0/s 30/m 5120/h 64100/d)
MCS2 downlink : 100997 (0/s 74/m 9806/h 97498/d)
MCS3 downlink : 163554 (0/s 125/m 16073/h 156786/d)
MCS4 downlink : 215425 (0/s 209/m 28530/h 201714/d)
MCS5 downlink : 193553 (0/s 443/m 23789/h 185733/d)
MCS6 downlink : 1486917 (41/s 4912/m 178715/h 1399590/d)
MCS7 downlink : 873804 (3/s 3047/m 98779/h 835575/d)
MCS8 downlink : 819444 (0/s 1588/m 83780/h 787885/d)
MCS9 downlink : 3229721 (103/s 5757/m 252395/h 3150371/d)
CS1 Uplink : 4349 (0/s 1/m 983/h 3403/d)
CS2 Uplink : 21078 (0/s 77/m 3026/h 18372/d)
CS3 Uplink : 42867 (3/s 158/m 9719/h 35157/d)
CS4 Uplink : 173909 (0/s 127/m 42036/h 141399/d)
MCS1 Uplink : 332914 (12/s 2802/m 40927/h 317392/d)
MCS2 Uplink : 326801 (2/s 232/m 29037/h 322189/d)
MCS3 Uplink : 497365 (0/s 551/m 54479/h 479085/d)
MCS4 Uplink : 285016 (6/s 1088/m 32257/h 272417/d)
MCS5 Uplink : 322464 (1/s 567/m 25867/h 312102/d)
MCS6 Uplink : 176673 (3/s 267/m 12749/h 171891/d)
MCS7 Uplink : 197133 (0/s 334/m 11796/h 191920/d)
MCS8 Uplink : 78434 (0/s 96/m 9522/h 75525/d)
MCS9 Uplink : 0 (0/s 0/m 0/h 0/d)
</pre> OsmoPCU - Bug #5293: Assert failed pdch != NULL encoding.cpp:561https://osmocom.org/issues/5293?journal_id=230632021-11-19T22:17:38Zkeith
<ul><li><strong>Assignee</strong> changed from <i>keith</i> to <i>pespin</i></li></ul><p><a class="user active" href="https://osmocom.org/users/30187">pespin</a> Can I leave this to you to close now, if you are happy with it, which I think you are?</p>
<p>I have not seen this assert again.</p> OsmoPCU - Bug #5293: Assert failed pdch != NULL encoding.cpp:561https://osmocom.org/issues/5293?journal_id=230672021-11-21T19:47:07Zpespin
<ul><li><strong>Status</strong> changed from <i>Feedback</i> to <i>Resolved</i></li><li><strong>% Done</strong> changed from <i>90</i> to <i>100</i></li></ul>