Actions
Bug #5264
closedASSERT in encoding.cpp:561
Start date:
10/14/2021
Due date:
% Done:
0%
Spec Reference:
Description
Assert failed pdch != NULL ../../git/src/encoding.cpp:561
Last (level ERROR) log line was:
DRLCMAC ERROR <0002> ../../git/src/pdch_ul_controller.c:159 PDCH(bts=0,trx=0,ts=7) FN=396881 Failed allocating POLL, all RRBP values are already reserved!
OsmoPCU 0.9.0.212-b9fe
BTS is 1.3.0 (release)
BSC, SGSN also are -latest (release)
Currently waiting for reproduction of this to add more info.
Related issues
Updated by pespin over 2 years ago
Please next time add a long log before the crash so I can understand better what went on before the crash.
Updated by keith over 2 years ago
(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 0x0003da68 in gen_freq_params (freq_params=<optimized out>, tbf=<optimized out>)
at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b9fede74ef-r0.18/git/src/encoding.cpp:561
#4 0x0003ead4 in write_packet_uplink_assignment (block=block@entry=0x1e2f00, old_tfi=old_tfi@entry=104 'h',
old_downlink=old_downlink@entry=0 '\000', tlli=tlli@entry=0, use_tlli=use_tlli@entry=1 '\001', tbf=0x391dc8,
tbf@entry=0x1, poll=poll@entry=1 '\001', rrbp=3 '\003', rrbp@entry=200 '\310', alpha=0 '\000',
alpha@entry=8 '\b', gamma=0 '\000', gamma@entry=3 '\003', ta_idx=ta_idx@entry=-1 '\377', use_egprs=true)
at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b9fede74ef-r0.18/git/src/encoding.cpp:676
#5 0x00031078 in create_packet_ul_assign (ctx=0x2cd6a0, d=d@entry=0xbefffabc)
at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b9fede74ef-r0.18/git/src/tbf_ul_ass_fsm.c:115
#6 0x000313b0 in st_send_ass (fi=0x1690f0, event=<optimized out>, data=0xbefffabc)
at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b9fede74ef-r0.18/git/src/tbf_ul_ass_fsm.c:185
#7 0xb6eb0480 in _osmo_fsm_inst_dispatch () from /usr/lib/libosmocore.so.17
#8 0x00031474 in tbf_ul_ass_create_rlcmac_msg (tbf=tbf@entry=0x2ae028, fn=fn@entry=7, ts=ts@entry=2 '\002')
at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b9fede74ef-r0.18/git/src/tbf_ul_ass_fsm.c:308
#9 0x00046ad8 in sched_select_ctrl_msg (block_nr=0 '\000', tbfs=<synthetic pointer>, fn=7, pdch=0x8c000)
at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b9fede74ef-r0.18/git/src/gprs_rlcmac_sched.cpp:202
---Type <return> to continue, or q <return> to quit---
#10 gprs_rlcmac_rcv_rts_block (bts=0x138748, trx=<optimized out>, ts=<optimized out>, fn=7, block_nr=3 '\003')
at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b9fede74ef-r0.18/git/src/gprs_rlcmac_sched.cpp:480
#11 0x000201e4 in pcu_rx_rts_req_pdtch (bts=<optimized out>, trx=<optimized out>, ts=<optimized out>,
fn=<optimized out>, block_nr=3 '\003')
at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b9fede74ef-r0.18/git/src/pcu_l1_if.cpp:518
#12 0x00015a44 in handle_ph_readytosend_ind (fl1h=0x140740, rts_ind=0x207050)
at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b9fede74ef-r0.18/git/src/osmo-bts-sysmo/sysmo_l1_if.c:148
#13 l1if_handle_l1prim (wq=<optimized out>, fl1h=0x140740, msg=0x206f88)
at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b9fede74ef-r0.18/git/src/osmo-bts-sysmo/sysmo_l1_if.c:287
#14 0xb6eabe10 in ?? () from /usr/lib/libosmocore.so.17
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
Updated by keith over 2 years ago
DTBF INFO <0008> ../../git/src/tbf_ul_ass_fsm.c:308 UL_ASS_TBF(UL-TFI_0)[0x1b6088]{SEND_ASS}: Received Event CREATE_RLCMAC_MSG [60/1783]
DTBFUL INFO <000a> ../../git/src/tbf_ul_ass_fsm.c:112 TBF(TFI=0 TLLI=0x9d92acae DIR=UL STATE=ASSIGN EGPRS) start Packet Uplink Assignment (PACCH)
DTBFUL INFO <000a> ../../git/src/tbf_ul_ass_fsm.c:131 TBF(TFI=0 TLLI=0x9d92acae DIR=UL STATE=ASSIGN EGPRS) Scheduled UL Assignment polling on PACCH (FN=398190, TS=7)
DTBF INFO <0008> ../../git/src/tbf_ul_ass_fsm.c:188 UL_ASS_TBF(UL-TFI_0)[0x1b6088]{SEND_ASS}: state_chg to WAIT_ACK
DRLCMAC NOTICE <0002> ../../git/src/pdch_ul_controller.c:330 PDCH(bts=0,trx=0,ts=7) Timeout for registered POLL (FN=398155, reason=UL_ASS): TBF(TFI=9 TLLI=0xf5f3b37e DIR=UL STATE=ASSIGN EG
PRS)
DTBF NOTICE <0008> ../../git/src/tbf.cpp:550 TBF(TFI=9 TLLI=0xf5f3b37e DIR=UL STATE=ASSIGN EGPRS) poll timeout for FN=398155, TS=7 (curr FN 398155)
DTBF INFO <0008> ../../git/src/tbf.cpp:589 UL_ASS_TBF(UL-TFI_9)[0x203a18]{WAIT_ACK}: Received Event ASS_POLL_TIMEOUT
DTBF NOTICE <0008> ../../git/src/tbf_ul_ass_fsm.c:224 TBF(TFI=9 TLLI=0xf5f3b37e 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> ../../git/src/tbf_ul_ass_fsm.c:226 UL_ASS_TBF(UL-TFI_9)[0x203a18]{WAIT_ACK}: state_chg to SEND_ASS
DTBF INFO <0008> ../../git/src/tbf_ul_ass_fsm.c:308 UL_ASS_TBF(UL-TFI_7)[0x1e2bb0]{SEND_ASS}: Received Event CREATE_RLCMAC_MSG
DRLCMAC ERROR <0002> ../../git/src/pdch_ul_controller.c:159 PDCH(bts=0,trx=0,ts=7) FN=398168 Failed allocating POLL, all RRBP values are already reserved!
DL1IF INFO <0001> ../../git/src/bts.cpp:1146 PH-DATA-IND is updating TBF(TFI=10 TLLI=0xa67fd7bc DIR=UL STATE=ASSIGN EGPRS): TA 4 -> 6 on TRX = 0
DRLCMAC INFO <0002> ../../git/src/gprs_ms.c:533 Modifying MS object, TLLI = 0xa67fd7bc, TA 4 -> 6
DRLCMAC NOTICE <0002> ../../git/src/pdch_ul_controller.c:330 PDCH(bts=0,trx=0,ts=7) Timeout for registered POLL (FN=398159, reason=UL_ASS): TBF(TFI=10 TLLI=0xa67fd7bc DIR=UL STATE=ASSIGN E
GPRS)
DTBF NOTICE <0008> ../../git/src/tbf.cpp:550 TBF(TFI=10 TLLI=0xa67fd7bc DIR=UL STATE=ASSIGN EGPRS) poll timeout for FN=398159, TS=7 (curr FN 398159)
DTBF INFO <0008> ../../git/src/tbf.cpp:589 UL_ASS_TBF(UL-TFI_10)[0x1dfb58]{WAIT_ACK}: Received Event ASS_POLL_TIMEOUT
DTBF NOTICE <0008> ../../git/src/tbf_ul_ass_fsm.c:224 TBF(TFI=10 TLLI=0xa67fd7bc 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> ../../git/src/tbf_ul_ass_fsm.c:226 UL_ASS_TBF(UL-TFI_10)[0x1dfb58]{WAIT_ACK}: state_chg to SEND_ASS
DTBF INFO <0008> ../../git/src/tbf_ul_ass_fsm.c:308 UL_ASS_TBF(UL-TFI_7)[0x1e2bb0]{SEND_ASS}: Received Event CREATE_RLCMAC_MSG
DTBFUL INFO <000a> ../../git/src/tbf_ul_ass_fsm.c:112 TBF(TFI=7 TLLI=0xe0ab04ca DIR=UL STATE=ASSIGN EGPRS) start Packet Uplink Assignment (PACCH)
DTBFUL INFO <000a> ../../git/src/tbf_ul_ass_fsm.c:131 TBF(TFI=7 TLLI=0xe0ab04ca DIR=UL STATE=ASSIGN EGPRS) Scheduled UL Assignment polling on PACCH (FN=398198, TS=7)
DTBF INFO <0008> ../../git/src/tbf_ul_ass_fsm.c:188 UL_ASS_TBF(UL-TFI_7)[0x1e2bb0]{SEND_ASS}: state_chg to WAIT_ACK
DL1IF INFO <0001> ../../git/src/bts.cpp:1146 PH-DATA-IND is updating TBF(TFI=11 TLLI=0xee1c9651 DIR=UL STATE=ASSIGN EGPRS): TA 4 -> 2 on TRX = 0
DRLCMAC INFO <0002> ../../git/src/gprs_ms.c:533 Modifying MS object, TLLI = 0xee1c9651, TA 4 -> 2
DRLCMAC NOTICE <0002> ../../git/src/pdch_ul_controller.c:330 PDCH(bts=0,trx=0,ts=7) Timeout for registered POLL (FN=398164, reason=UL_ASS): TBF(TFI=11 TLLI=0xee1c9651 DIR=UL STATE=ASSIGN E
GPRS)
DTBF NOTICE <0008> ../../git/src/tbf.cpp:550 TBF(TFI=11 TLLI=0xee1c9651 DIR=UL STATE=ASSIGN EGPRS) poll timeout for FN=398164, TS=7 (curr FN 398164)
DTBF INFO <0008> ../../git/src/tbf.cpp:589 UL_ASS_TBF(UL-TFI_11)[0x32ff70]{WAIT_ACK}: Received Event ASS_POLL_TIMEOUT
DTBF NOTICE <0008> ../../git/src/tbf_ul_ass_fsm.c:224 TBF(TFI=11 TLLI=0xee1c9651 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> ../../git/src/tbf_ul_ass_fsm.c:226 UL_ASS_TBF(UL-TFI_11)[0x32ff70]{WAIT_ACK}: state_chg to SEND_ASS
DTBF INFO <0008> ../../git/src/tbf_ul_ass_fsm.c:308 UL_ASS_TBF(UL-TFI_8)[0x1690f0]{SEND_ASS}: Received Event CREATE_RLCMAC_MSG
DTBFUL INFO <000a> ../../git/src/tbf_ul_ass_fsm.c:112 TBF(TFI=0 TLLI=0xf1cf357d DIR=UL STATE=ASSIGN) start Packet Uplink Assignment (PACCH)
Assert failed pdch != NULL ../../git/src/encoding.cpp:561
Updated by keith over 2 years ago
Here's the tbf in write_packet_uplink_assignment()
(gdb) p *tbf
$10 = {<gprs_rlcmac_tbf> = {_vptr.gprs_rlcmac_tbf = 0x8b828 <vtable for gprs_rlcmac_ul_tbf+8>,
direction = GPRS_RLCMAC_UL_TBF, trx = 0x138774, first_ts = 0 '\000', first_common_ts = 0 '\000',
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 = 0x138748, m_tfi = 0 '\000', m_created_ts = 0, m_ctrs = 0x208090, state_fsm = {fi = 0x204e28,
tbf = 0x391dc8, state_flags = 2, T_release = 0}, ul_ass_fsm = {fi = 0x207dc0, tbf = 0x391dc8}, dl_ass_fsm = {
fi = 0x207eb0, tbf = 0x391dc8}, m_ms_list = {list = {next = 0x0, prev = 0x0}, entry = 0x391dc8}, m_trx_list = {
list = {next = 0x30e5ec, prev = 0x32ed84}, entry = 0x391dc8}, m_ms = 0x18a960, 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=0 TLLI=0xf1cf357d DIR=UL STATE=ASSIGN)\000S)\000\000\000\000\000\000\000\000\000\000"},
m_rx_counter = 0, m_usf = "\377\377\377\377\377\377\377\377", m_contention_resolution_done = 0 '\000',
m_ul_gprs_ctrs = 0x208450, m_ul_egprs_ctrs = 0x208130, ul_ack_fsm = {fi = 0x207fa0, tbf = 0x391dc8},
m_window = {<gprs_rlc_window> = {m_sns = 128, m_ws = 64}, m_v_r = 0, m_v_q = 0, m_v_n = {m_v_n = {
GPRS_RLC_UL_BSN_INVALID <repeats 1024 times>}}}}
Updated by pespin over 2 years ago
- Is duplicate of Bug #5207: Crash: ABRT on current master 945be910 with "Assert failed pdch != NULL encoding.cpp:561" added
Updated by pespin over 2 years ago
- Assignee changed from pespin to keith
Hi keith , can you check if you still get this issue with current osmo-pcu.git master b0aba591433c7c22298035453713724172d1cfbc?
Updated by keith over 2 years ago
Program received signal SIGABRT, Aborted.
0x425bcf74 in raise () from /lib/libc.so.6
(gdb) bt
#0 0x425bcf74 in raise () from /lib/libc.so.6
#1 0x425be358 in abort () from /lib/libc.so.6
#2 0xb6e2b0d8 in osmo_panic () from /usr/lib/libosmocore.so.17
#3 0x0003db50 in gen_freq_params (freq_params=<optimized out>, tbf=<optimized out>) at/usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b0aba59143-r0.18/git/src/encoding.cpp:561
#4 0x0003ebbc in write_packet_uplink_assignment (block=block@entry=0x352a790, old_tfi=old_tfi@entry=56 '8', old_downlink=old_downlink@entry=0 '\000', tlli=tlli@entry=0,
use_tlli=use_tlli@entry=1 '\001', tbf=0x354af28, tbf@entry=0x1, poll=poll@entry=1 '\001', rrbp=2 '\002', rrbp@entry=40 '(', alpha=0 '\000', alpha@entry=14 '\016',
gamma=0 '\000', gamma@entry=2 '\002', ta_idx=ta_idx@entry=-1 '\377', use_egprs=true) at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b0aba59143-r0.18/git/src/encoding.cpp:676
#5 0x00031110 in create_packet_ul_assign (ctx=0x1558c68, d=d@entry=0xbef3db8c) at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b0aba59143-r0.18/git/src/tbf_ul_ass_fsm.c:116
#6 0x000314b0 in st_send_ass (fi=0x1ce2c8, event=<optimized out>, data=0xbef3db8c) at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b0aba59143-r0.18/git/src/tbf_ul_ass_fsm.c:189
#7 0xb6e21480 in _osmo_fsm_inst_dispatch () from /usr/lib/libosmocore.so.17
#8 0x00031558 in tbf_ul_ass_create_rlcmac_msg (tbf=tbf@entry=0x15395f0, fn=fn@entry=7,ts=ts@entry=2 '\002')
at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b0aba59143-r0.18/git/src/tbf_ul_ass_fsm.c:337
#9 0x00046bc0 in sched_select_ctrl_msg (block_nr=0 '\000', tbfs=<synthetic pointer>, fn=7, pdch=0x8c000)
at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b0aba59143-r0.18/git/src/gprs_rlcmac_sched.cpp:202
#10 gprs_rlcmac_rcv_rts_block (bts=0x138770, trx=<optimized out>, ts=<optimized out>, fn=7, block_nr=1 '\001')
at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b0aba59143-r0.18/git/src/gprs_rlcmac_sched.cpp:480
#11 0x000201e0 in pcu_rx_rts_req_pdtch (bts=<optimized out>, trx=<optimized out>, ts=<optimized out>, fn=<optimized out>, block_nr=1 '\001')
at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b0aba59143-r0.18/git/src/pcu_l1_if.cpp:518
#12 0x00015a40 in handle_ph_readytosend_ind (fl1h=0x1402d0, rts_ind=0x3b5648) at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b0aba59143-r0.18/git/src/osmo-bts-sysmo/sysmo_l1_if.c:148
#13 l1if_handle_l1prim (wq=<optimized out>, fl1h=0x1402d0, msg=0x3b5580) at /usr/src/debug/osmo-pcu/0.9.0+gitAUTOINC+b0aba59143-r0.18/git/src/osmo-bts-sysmo/sysmo_l1_if.c:287
#14 0xb6e1ce10 in ?? () from /usr/lib/libosmocore.so.17
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
Updated by keith over 2 years ago
I'm not sure what to look for, Don't know if this lead up log helps
DRLCMAC <0002> ../../git/src/gprs_ms.c:301 MS(TLLI=0xfa2ff455, IMSI=000, TA=3, 12/12, UL) Attaching UL TBF: TBF(TFI=3 TLLI=0xfa2ff455 DIR=UL STATE=NEW EGPRS)
DTBFUL <000a> ../../git/src/tbf_ul.cpp:740 TBF(TFI=3 TLLI=0xfa2ff455 DIR=UL STATE=NEW EGPRS) setting EGPRS UL window size to 64, base(64) slots(1) ws_pdch(0)
DRLCMAC <0002> ../../git/src/rlc.cpp:249 ws(64)
DTBF <0008> ../../git/src/tbf_ul.cpp:167 TBF(UL-TFI_3)[0x313560]{NEW}: Received Event ASSIGN_ADD_PACCH
DTBF <0008> ../../git/src/tbf_fsm.c:89 TBF(TFI=3 TLLI=0xfa2ff455 DIR=UL STATE=NEW EGPRS) set ass. type PACCH [prev CCCH:0, PACCH:0]
DTBF <0008> ../../git/src/tbf_fsm.c:111 TBF(UL-TFI_3)[0x313560]{NEW}: state_chg to ASSIGN
DTBF <0008> ../../git/src/pdch.cpp:728 UL_ASS_TBF(UL-TFI_3)[0x1d0c20]{NONE}: Received Event SCHED_ASS
DTBF <0008> ../../git/src/tbf_ul_ass_fsm.c:168 UL_ASS_TBF(UL-TFI_3)[0x1d0c20]{NONE}: state_chg to SEND_ASS
DRLCMACMEAS <0007> ../../git/src/gprs_ms.c:743 MS(TLLI=0xfa2ff455, IMSI=000, TA=3, 12/12, UL) Link quality 4dB (old 6dB) left window [7, 13], modifying uplink CS level: MCS-3 -> MCS-2
DTBFDL <0009> ../../git/src/tbf_dl.cpp:983 TBF(TFI=4 TLLI=0xf5a70316 DIR=DL STATE=FLOW EGPRS) Scheduled Ack/Nack polling on FN=306475, TS=4
DTBF <0008> ../../git/src/tbf_ul_ass_fsm.c:337 UL_ASS_TBF(UL-TFI_3)[0x1d0c20]{SEND_ASS}: Received Event CREATE_RLCMAC_MSG
DTBFUL <000a> ../../git/src/tbf_ul_ass_fsm.c:113 TBF(TFI=3 TLLI=0xfa2ff455 DIR=UL STATE=ASSIGN EGPRS) start Packet Uplink Assignment (PACCH)
DCSN1 <0000> ../../git/src/gsm_rlcmac.c:5878 csnStreamEncoder (type: Pkt UL ASS (10)):
DTBFUL <000a> ../../git/src/tbf_ul_ass_fsm.c:132 TBF(TFI=3 TLLI=0xfa2ff455 DIR=UL STATE=ASSIGN EGPRS) Scheduled UL Assignment polling on PACCH (FN=306475, TS=7)
DTBF <0008> ../../git/src/tbf_ul_ass_fsm.c:192 UL_ASS_TBF(UL-TFI_3)[0x1d0c20]{SEND_ASS}: state_chg to WAIT_ACK
DLNSDATA <0024> ../../../git/src/gb/gprs_ns2.c:1311 NSE(00103)-NSVC(00103) Rx NS-UNITDATA
DLNSDATA <0024> ../../../git/src/gb/gprs_ns2_vc_fsm.c:671 NSE(00103)-NSVC(00103) Rx NS-UNITDATA
DCSN1 <0000> ../../git/src/gsm_rlcmac.c:6171 csnStreamDecoder (RAcap):
DLBSSGP <0023> ../../git/src/gprs_bssgp_pcu.c:182 LLC [SGSN -> PCU] = TLLI: 0xc497eecf IMSI: 334020508554888 len: 124
DRLCMACUL <0005> ../../git/src/pdch.cpp:971 PDCH(bts=0,trx=0,ts=5) Got MCS-3 RLC block: R=0, SI=0, TFI=3, CPS=3, RSB=0, rc=329
DLBSSGP <0023> ../../git/src/tbf_ul.cpp:538 LLC [PCU -> SGSN] TBF(TFI=3 TLLI=0xc497eecf DIR=UL STATE=FLOW EGPRS) len=50
DLNSDATA <0024> ../../../git/src/gb/gprs_ns2_message.c:426 NSE(00103)-NSVC(00103) Tx NS-UNITDATA
DRLCMAC <0002> ../../git/src/pdch_ul_controller.c:330 PDCH(bts=0,trx=0,ts=7) Timeout for registered POLL (FN=306453, reason=DL_ACK): TBF(TFI=0 TLLI=0xf9513dc8 DIR=DL STATE=FLOW EGPRS)
DTBF <0008> ../../git/src/tbf.cpp:551 TBF(TFI=0 TLLI=0xf9513dc8 DIR=DL STATE=FLOW EGPRS) poll timeout for FN=306453, TS=7 (curr FN 306453)
DTBF <0008> ../../git/src/tbf.cpp:629 TBF(TFI=0 TLLI=0xf9513dc8 DIR=DL STATE=FLOW EGPRS) Timeout for polling PACKET DOWNLINK ACK: |Assignment was on PACCH|Downlink ACK was received|
DTBF <0008> ../../git/src/tbf.cpp:645 TBF(DL-TFI_0)[0x23b688]{FLOW}: Received Event DL_ACKNACK_MISS
DTBFDL <0009> ../../git/src/tbf_dl.cpp:983 TBF(TFI=0 TLLI=0xf9513dc8 DIR=DL STATE=FLOW EGPRS) Scheduled Ack/Nack polling on FN=306479, TS=7
DCSN1 <0000> ../../git/src/gsm_rlcmac.c:5394 csnStreamDecoder (type: Pkt Control Ack (1)):
DTBFUL <000a> ../../git/src/pdch.cpp:357 UL_ACK_TBF(UL-TFI_0)[0x1270b88]{WAIT_ACK}: Received Event RX_CTRL_ACK
DTBFUL <000a> ../../git/src/tbf_ul_ack_fsm.c:153 UL_ACK_TBF(UL-TFI_0)[0x1270b88]{WAIT_ACK}: state_chg to NONE
DTBF <0008> ../../git/src/pdch.cpp:360 TBF(UL-TFI_0)[0x1d19e0]{FINISHED}: Received Event FINAL_UL_ACK_CONFIRMED
DTBF <0008> ../../git/src/tbf.cpp:291 TBF(TFI=0 TLLI=0xe1e63294 DIR=UL STATE=FINISHED EGPRS) free
DRLCMAC <0002> ../../git/src/pdch.cpp:1153 PDCH(bts=0,trx=0,ts=5) Detaching TBF(TFI=0 TLLI=0xe1e63294 DIR=UL STATE=FINISHED EGPRS), 5 TBFs, USFs = 3e, TFIs = 0000048e.
DRLCMAC <0002> ../../git/src/gprs_ms.c:369 MS(TLLI=0xe1e63294, IMSI=334020157765392, TA=5, 12/12, DL) Detaching TBF: TBF(TFI=0 TLLI=0xe1e63294 DIR=UL STATE=FINISHED EGPRS)
DTBFUL <000a> ../../git/src/fsm.c:573 UL_ACK_TBF(UL-TFI_0)[0x1270b88]{NONE}: Deallocated
DTBF <0008> ../../git/src/fsm.c:573 TBF(UL-TFI_0)[0x1d19e0]{FINISHED}: Deallocated
DTBF <0008> ../../git/src/fsm.c:573 UL_ASS_TBF(UL-TFI_0)[0x1d0f80]{NONE}: Deallocated
DTBF <0008> ../../git/src/fsm.c:573 DL_ASS_TBF(UL-TFI_0)[0x3e0530]{NONE}: Deallocated
DRLCMACUL <0005> ../../git/src/pdch.cpp:971 PDCH(bts=0,trx=0,ts=7) Got MCS-1 RLC block: R=0,
Updated by pespin over 2 years ago
So the summary here is that this assert fails:
/* Check one PDCH, if it's hopping then all other should too */
pdch = tbf->pdch[tbf->first_ts];
OSMO_ASSERT(pdch != NULL);
The check looks good to me and I'm not yet fully understanding how a TBF can end up with "tbf->pdch[tbf->first_ts]" being NULL. That probably happens because the the PDCH TS was detached at some point, but I'm lacking information from the pdch and tbf objects to understand better the conditions, as well as more verbose and longer logging to find out how it ended up that way.
Updated by pespin over 2 years ago
I also looked at the previous trace:
This from TBF looks interesting: "first_common_ts = 0 '\000', control_ts = 7 '\a', pdch = {0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}"
So no pdch attached, that indeed is really suspicious. Not sure how it can happen though. Maybe some error path in allocation failing we are not properly handling? It'd be great to have way longer logs (wuth INFO if possible) to see the entire lifcycle of that TBF.
Updated by pespin over 2 years ago
Possible hint: It may be that TBF is properly allocated but at some time all the TBFs become disabled (eg dynamic TS) and we end up in that state? That shouldn't happen because pdch->disable() == pdch->free_resources() gets rid of all those TBFs in theory.
Updated by keith over 2 years ago
- Related to Bug #5293: Assert failed pdch != NULL encoding.cpp:561 added
Actions
