Project

General

Profile

Actions

Bug #5293

closed

Assert failed pdch != NULL encoding.cpp:561

Added by keith 21 days ago. Updated 6 days ago.

Status:
Resolved
Priority:
High
Assignee:
Target version:
-
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

pcu.log.gz pcu.log.gz 1.14 MB keith, 11/08/2021 07:39 PM
tmux-buffer.txt tmux-buffer.txt 235 KB keith, 11/10/2021 05:11 AM
c_log.txt c_log.txt 288 KB keith, 11/10/2021 08:31 PM

Related issues

Related to OsmoPCU - Bug #5264: ASSERT in encoding.cpp:561Resolvedkeith10/14/2021

Actions
Actions #1

Updated by keith 21 days 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
Actions #2

Updated by keith 21 days 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

https://www.rhizomatica.org/files/OS_5293-1.zip

Actions #3

Updated by keith 21 days ago

  • Related to Bug #5264: ASSERT in encoding.cpp:561 added
Actions #4

Updated by keith 21 days ago

pespin just looking at your notes on #5264 - 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.

Actions #5

Updated by laforge 21 days 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.

Actions #6

Updated by keith 19 days 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.

Actions #7

Updated by pespin 19 days 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.

Actions #8

Updated by keith 19 days 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.

Actions #9

Updated by keith 19 days ago

Attaching complete log from start to ASSERT.

OsmoPCU version 0.9.0.259-ef8a

Actions #10

Updated by keith 18 days 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 :(

Actions #11

Updated by keith 17 days ago

Caught one of these fairly soon after startup

Actions #12

Updated by keith 17 days 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"}

Actions #13

Updated by pespin 17 days 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

Actions #14

Updated by pespin 17 days 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}

Actions #15

Updated by pespin 17 days 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.

Actions #16

Updated by keith 17 days 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!
Actions #17

Updated by keith 17 days ago

I hit CTRL-S in the terminal to capture this [c_log.txt], of course, then the process exited.

I'll try again and then see if I can stop and inspect the relevant objects in gdb

Actions #18

Updated by pespin 16 days 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.

Actions #19

Updated by keith 15 days 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)

Actions #20

Updated by keith 7 days 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.

Actions #21

Updated by pespin 6 days ago

  • Status changed from Feedback to Resolved
  • % Done changed from 90 to 100
Actions

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)