Cellular Network Infrastructure » Radio Access Network » OsmoPCU

I've seen this now with a different call stack but it looks like the same kaboom.

Log Tail Type 2¶

<0002> gprs_rlcmac_ts_alloc.cpp:776 No USF available
<0008> tbf.cpp:746 TBF(TFI=0 TLLI=0x78474a51 DIR=UL STATE=NULL EGPRS) Timeslot Allocation failed: trx = 1, single_slot = 0
<0008> tbf_ul.cpp:151 MS(TLLI=0x78474a51, IMSI=618010111567897, TA=0, 12/12, DL) No PDCH resource
<0002> pdch_ul_controller.c:315 PDCH(bts=0,trx=1,ts=6) Expiring FN=1792717 but previous FN=1792708 is still reserved!
<0002> pdch_ul_controller.c:315 PDCH(bts=0,trx=1,ts=6) Expiring FN=1792717 but previous FN=1792713 is still reserved!
<0002> pdch_ul_controller.c:329 PDCH(bts=0,trx=1,ts=6) Timeout for registered POLL (FN=1792713): TBF(TFI=3 TLLI=0xe2569340 DIR=DL STATE=FLOW EGPRS)
<0008> tbf.cpp:629 TBF(TFI=3 TLLI=0xe2569340 DIR=DL STATE=FLOW EGPRS) poll timeout for FN=1792713, TS=6 (curr FN 1792717)
<0008> tbf.cpp:699 TBF(TFI=3 TLLI=0xe2569340 DIR=DL STATE=FLOW EGPRS) Timeout for polling PACKET DOWNLINK ACK: |Assignment was on PACCH|Downlink ACK was received|
<0002> pdch_ul_controller.c:315 PDCH(bts=0,trx=1,ts=6) Expiring FN=1792734 but previous FN=1792721 is still reserved!
<0002> pdch_ul_controller.c:315 PDCH(bts=0,trx=1,ts=6) Expiring FN=1792734 but previous FN=1792726 is still reserved!
<0002> pdch_ul_controller.c:315 PDCH(bts=0,trx=1,ts=6) Expiring FN=1792734 but previous FN=1792730 is still reserved!
<0002> pdch_ul_controller.c:315 PDCH(bts=0,trx=1,ts=7) Expiring FN=1792734 but previous FN=1792730 is still reserved!
<0008> tbf.cpp:458 TBF(TFI=7 TLLI=0xcb2f0a00 DIR=DL STATE=WAIT_RELEASE EGPRS) T3193 timeout expired, freeing TBF
<0008> tbf.cpp:465 TBF(TFI=7 TLLI=0xcb2f0a00 DIR=DL STATE=WAIT_RELEASE EGPRS) T3193 timeout expired, freeing TBF
<0008> tbf.cpp:458 TBF(TFI=14 TLLI=0xee10ac00 DIR=DL STATE=WAIT_RELEASE EGPRS T3193 timeout expired, freeing TBF
<0008> tbf.cpp:465 TBF(TFI=14 TLLI=0xee10ac00 DIR=DL STATE=WAIT_RELEASE EGPRS T3193 timeout expired, freeing TBF
<0002> pdch_ul_controller.c:329 PDCH(bts=0,trx=1,ts=6) Timeout for registered POLL (FN=1792743): TBF(TFI=31 TLLI=0x7c31afb2 DIR=DL STATE=FLOW EGPRS)
<0008> tbf.cpp:629 TBF(TFI=31 TLLI=0x7c31afb2 DIR=DL STATE=FLOW EGPRS) poll timeout for FN=1792743, TS=6 (curr FN 1792743)
<0008> tbf.cpp:699 TBF(TFI=31 TLLI=0x7c31afb2 DIR=DL STATE=FLOW EGPRS) Timeout for polling PACKET DOWNLINK ACK: |Assignment was on PACCH|Downlink ACK was received|
<0002> pdch_ul_controller.c:315 PDCH(bts=0,trx=1,ts=7) Expiring FN=1792743 but previous FN=1792739 is still reserved!
<0008> tbf.cpp:407 TBF(TFI=7 TLLI=0xa86f0e0e DIR=UL STATE=FLOW EGPRS) N3101 exceeded MAX (10)
<0002> gprs_rlcmac_ts_alloc.cpp:776 No USF available
<0008> tbf.cpp:746 TBF(TFI=0 TLLI=0x7e64c836 DIR=UL STATE=NULL EGPRS) Timeslot Allocation failed: trx = 1, single_slot = 0
<0008> tbf_ul.cpp:151 MS(TLLI=0x7e64c836, IMSI=618010111603467, TA=0, 12/12, DL) No PDCH resource
<0008> tbf.cpp:458 TBF(TFI=9 TLLI=0x8d2aa800 DIR=UL STATE=RELEASING EGPRS) T3169 timeout expired, freeing TBF
<0008> tbf.cpp:462 TBF(TFI=9 TLLI=0x8d2aa800 DIR=UL STATE=RELEASING EGPRS) T3169 timeout expired, freeing TBF: |Assignment was on PACCH|No uplink data received yet|
<0002> pdch_ul_controller.c:315 PDCH(bts=0,trx=1,ts=7) Expiring FN=1792760 but previous FN=1792747 is still reserved!

Backtrace Type 2¶

Program received signal SIGSEGV, Segmentation fault.
0x00007ffff6c92110 in osmo_fsm_state_name () from /usr/lib64/libosmocore.so.17
#0  0x00007ffff6c92110 in osmo_fsm_state_name () from /usr/lib64/libosmocore.so.17
#1  0x0000000000418fe3 in osmo_fsm_inst_state_name (fi=<optimized out>) at /root/builder/firmware-master/build/rangesdmn-x86-64-core2/usr/include/osmocom/core/fsm.h:233
#2  gprs_rlcmac_tbf::state_name (this=0xe1fb80) at ./tbf.h:370
#3  gprs_rlcmac_tbf::name (this=0xe1fb80) at tbf.cpp:1070
#4  0x000000000041905a in tbf_name (tbf=<optimized out>) at tbf.cpp:1065
#5  0x000000000042ad01 in pdch_ulc_expire_fn (ulc=0x7bd690, fn=fn@entry=1792760) at pdch_ul_controller.c:327
#6  0x000000000040ff0b in pcu_rx_data_ind_pdtch (bts=bts@entry=0x7ad200, pdch=pdch@entry=0x7af720, data=data@entry=0x7fffffffe326 "@\005\341\063\354\233", '+' <repeats 17 times>, len=<optimized out>, fn=1792760, meas=meas@entry=0x7fffffffe2a0) at pcu_l1_if.cpp:285
#7  0x0000000000410834 in pcu_rx_data_ind (data_ind=0x7fffffffe324, bts=0x7ad200) at pcu_l1_if.cpp:418
#8  pcu_rx (pcu_prim=pcu_prim@entry=0x7fffffffe320, pcu_prim_length=<optimized out>) at pcu_l1_if.cpp:992
#9  0x0000000000431399 in pcu_sock_read (bfd=<optimized out>) at osmobts_sock.c:156
#10 0x0000000000431585 in pcu_sock_cb (bfd=0x6974e0 <pcu_sock_state>, flags=1) at osmobts_sock.c:211
#11 0x00007ffff6c8e78c in ?? () from /usr/lib64/libosmocore.so.17
#12 0x00007ffff6c8e836 in osmo_select_main () from /usr/lib64/libosmocore.so.17
#13 0x0000000000406bf5 in main (argc=1, argv=0x7fffffffecd8) at pcu_main.cpp:329
$1 = {si_signo = 11, si_errno = 0, si_code = 1, _sifields = {_pad = {48, 0, 160, 0, 70288, 0, 50806128, 0, 816916108, 32764, 951191690, 32604, 1, 0, 160, 0, 38817760, 0, 47792368, 0, 44, 0, 6622689, 0, 8149536, 0, 45656064, 0}, _kill = {si_pid = 48, si_uid = 0}, _timer = {si_tid = 48, si_overrun = 0, si_sigval = {sival_int = 160, sival_ptr = 0xa0}}, _rt = {si_pid = 48, si_uid = 0, si_sigval = {sival_int = 160, sival_ptr = 0xa0}}, _sigchld = {si_pid = 48, si_uid = 0, si_status = 160, si_utime = 301884661301248, si_stime = 218210658196389888}, _sigfault = {si_addr = 0x30, _addr_lsb = 160, _addr_bnd = {_lower = 0x11290, _upper = 0x3073d70}}, _sigpoll = {si_band = 48, si_fd = 160}}}

The code where the SEGV is reported:

const char *tbf_name(const gprs_rlcmac_tbf *tbf) 
{                
        return tbf ? tbf->name() : "(no TBF)";
}

const char *gprs_rlcmac_tbf::name() const
{
        snprintf(m_name_buf, sizeof(m_name_buf) - 1,
                "TBF(TFI=%d TLLI=0x%08x DIR=%s STATE=%s%s)",
                m_tfi, tlli(),
                direction == GPRS_RLCMAC_UL_TBF ? "UL" : "DL",
                state_name(),
                is_egprs_enabled() ? " EGPRS" : "" 
                );
        m_name_buf[sizeof(m_name_buf) - 1] = '\0';
        return m_name_buf;
}

AFAICT this cannot be a NULL dereference.

• tbf_name() checks against NULL tbf
• tlli() checks against a NULL m_ms
• state_name() uses osmo_fsm_inst_state_name() which is NULL safe
• state_fsm is a member struct and cannot be NULL
• is_gprs_enabled() merely returns a bool member

Since it's not a NULL deref, I guess it must be a use-after-free??

seems that the ulc->tree_root traversed in pdch_ulc_expire_fn() upon receiving a pdtch data ind
still points at a entry that has already been deallocated.

I'm pretty sure that the actual cause for the error happens way before the symptom shows:
at some point a tbf gets freed without calling tbf_free(), and it busts up pdch_ulc_expire_fn() some time later.

The reason is not trivial: tbf_free() properly calls tbf_unlink_pdch() that
removes the tbf entry via gprs_rlcmac_pdch::detach_tbf() and pdch_ulc_release_tbf()

Next checking whether:

• some error handling path frees a tbf in a different way,
• some parent talloc ctx might be freed and "pulls the carpet".

If I don't find any cause, we could add some strategic logging and analyse allocation and freeing next time it happens.

Same as #5205, let's ask iedemam if he stills sees it with recent versions of osmo-pcu after FSM refactoring was merged (end of August).

I believe this should be fixed in current osmo-pcu.git master b0aba591433c7c22298035453713724172d1cfbc

Please iedemam see if you can still reproduce.

pespin wrote:

I believe this should be fixed in current osmo-pcu.git master b0aba591433c7c22298035453713724172d1cfbc

Please iedemam see if you can still reproduce.

any update here, can the issue be closed?

Also looking good here, thanks. Can be closed.