Actions
Bug #5293
closedAssert failed pdch != NULL encoding.cpp:561
Start date:
11/06/2021
Due date:
% Done:
100%
Spec Reference:
Description
This one is happening repeatedly:
#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 0x0004f51c in gen_freq_params(Frequency_Parameters_t*, gprs_rlcmac_tbf const*) () #4 0x0004f8d4 in write_packet_uplink_assignment () #5 0x0003a1a0 in create_packet_ul_assign () #6 0x0003a540 in st_send_ass () #7 0xb6eb0480 in _osmo_fsm_inst_dispatch () from /usr/lib/libosmocore.so.17 #8 0x0003a5e8 in tbf_ul_ass_create_rlcmac_msg () #9 0x0005c2a0 in sched_select_ctrl_msg(gprs_rlcmac_pdch*, unsigned int, unsigned char, tbf_sched_candidates*) () #10 0x0005d448 in gprs_rlcmac_rcv_rts_block(gprs_rlcmac_bts*, unsigned char, unsigned char, unsigned int, unsigned char) () #11 0x00023888 in pcu_rx_rts_req_pdtch () #12 0x00015e7c in l1if_handle_l1prim () #13 0xb6eabe10 in ?? () from /usr/lib/libosmocore.so.17 Backtrace stopped: previous frame identical to this frame (corrupt stack?)
Files
Related issues
Updated by keith over 2 years ago
Somehow I lost the process in gdb, but here's a slightly better backtrace....
#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
and some lead up log...
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
Updated by keith over 2 years ago
Once Again.
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)
(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.
Sending on core and binary anyway.
(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
Limited lead up log in the hopes something there is useful.
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
Updated by keith over 2 years ago
- Related to Bug #5264: ASSERT in encoding.cpp:561 added
Updated by laforge over 2 years ago
- Assignee set to pespin
- Priority changed from Normal to High
pespin 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.
Updated by keith over 2 years ago
keith wrote in #note-4:
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.
no luck with that. I cannot force the crash this way. Probably I need lots more activity than just one phone.
Updated by pespin over 2 years ago
Hi keith , I submitted a bunch of patches whcih may help with fixing/improving the situation:
remote: https://gerrit.osmocom.org/c/osmo-pcu/+/26151 tbf: Increase log level of line about unable to allocate poll for TBF
remote: https://gerrit.osmocom.org/c/osmo-pcu/+/26152 pdch: Improve log line and increase log level
remote: https://gerrit.osmocom.org/c/osmo-pcu/+/26154 tbf_ul: Set first_(common_)ts in handle_tbf_reject [NEW]
remote: https://gerrit.osmocom.org/c/osmo-pcu/+/26155 tbf: Set m_created_ts in constructor [NEW]
remote: https://gerrit.osmocom.org/c/osmo-pcu/+/26156 tbf: Mark initial first_(common_)ts with special value [NEW]
remote: https://gerrit.osmocom.org/c/osmo-pcu/+/26157 tbf: Set tfi to initial special value [NEW]
remote: https://gerrit.osmocom.org/c/osmo-pcu/+/26158 tbf_ul: Update FSM names for dummy reject TBFs [NEW]
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.
Regarding the debug info: Since osmo-pcu is partly C++, remember CFLAGS alone won't work. Better pass CXXFLAGS too.
Updated by keith over 2 years ago
Thanks Pau, I will build and install that now. (with CXXFLAGS)
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
Also, just to be complete, osmo-bsc and sgsn etc are "latest", not master/nightly.
Updated by keith over 2 years ago
- File pcu.log.gz pcu.log.gz added
Attaching complete log from start to ASSERT.
OsmoPCU version 0.9.0.259-ef8a
Updated by keith over 2 years ago
Here is another log and core for this one: https://www.rhizomatica.org/files/5293-2.zip
EDIT: sorry, just noticed the log ends before the crash due to out of disk space again :(
Updated by keith over 2 years ago
- File tmux-buffer.txt tmux-buffer.txt added
Caught one of these fairly soon after startup
Updated by keith over 2 years ago
(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"}
Updated by pespin over 2 years ago
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.
I believe this patch should improve the situation and avoid resources being reserved for longer time than needed:
https://gerrit.osmocom.org/c/osmo-pcu/+/26198 pdch: Drop previous UL TBF from MS who sent PktResReq through SBA
Updated by pespin over 2 years ago
Ok, thanks to my last patches improving logging I now understand what's happening.
First a UL TBF is created for the MS (TFI=0):
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
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.
Now, this is how it works (tbf_ul_ass_fsm.c create_packet_ul_assign()):
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;
}
It goes one sending Pkt Ul Ass but itis never answered.
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:
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
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:
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
TFI=-1 has no attached TBF, hence calling "gen_freq_params(fp, tbf);" on it will crash, due to:
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}
Updated by pespin over 2 years ago
- Status changed from New to Feedback
- Assignee changed from pespin to keith
- % Done changed from 0 to 90
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.
https://gerrit.osmocom.org/c/osmo-pcu/+/26198 pdch: Drop previous UL TBF from MS who sent PktResReq through SBA
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.
Please keith , give it a try ASAP and provide some feedback.
Updated by keith over 2 years ago
Hi pespin
What I'm seeing now is this log repeating rapidly (quite some entries per second):
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!
Updated by pespin over 2 years ago
Hi keith , it seems you run through a missing transition there. It's fixed here:
https://gerrit.osmocom.org/c/osmo-pcu/+/26208 tbf_dl_ass_fsm: Fix missing transition to NONE if DL TBF is nonexistent
Please give it a try when you find some time, I hope we are finally sorting out all big issues.
Updated by keith over 2 years ago
Hi pespin
I have been running these patches now for about 20 hours with no crash or visible issues.
Thanks for all the amazing work!
Here's the stats from running pcu it case it's of interest:
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)
Updated by keith over 2 years ago
- Assignee changed from keith to pespin
pespin Can I leave this to you to close now, if you are happy with it, which I think you are?
I have not seen this assert again.
Updated by pespin over 2 years ago
- Status changed from Feedback to Resolved
- % Done changed from 90 to 100
Actions
