Kamailio 5.3 bc5970811d coredump

[smititelu]

Description

Hello, I'm being stuck at debugging a coredump for kamailio 5.3. built at bc59708 commit, that happened when receiving/forwarding 100 Trying. It is not easily reproducible.

I'm stuck at question 1 and 2, below. Please let me know if you have any other ideas of what is happening. Thank you.

Debugging Data

(gdb) bt
#0  0x00005593f836b822 in match_by_name (avp=0xc, id=105, name=0x7ffc060813a8) at core/usr_avp.c:378
#1  0x00005593f836c670 in search_next_avp (s=0x7ffc060813a0, val=0x7ffc06081380) at core/usr_avp.c:499
#2  0x00005593f836c02c in search_avp (ident=..., val=0x7ffc06081380, state=0x7ffc060813a0) at core/usr_avp.c:465
#3  0x00005593f836b9a6 in search_first_avp (flags=1, name=..., val=0x7ffc06081380, s=0x7ffc060813a0) at core/usr_avp.c:414
#4  0x00007f82877df246 in pv_get_avp (msg=0x7f82890e0708, param=0x7f8288ce18d0, res=0x7ffc060814e0) at pv_core.c:1793
#5  0x00005593f839b872 in pv_get_spec_value (msg=0x7f82890e0708, sp=0x7f8288ce18b8, value=0x7ffc060814e0) at core/pvapi.c:1404
#6  0x00005593f81b88f2 in rv_defined (h=0x7ffc06082f80, msg=0x7f82890e0708, res=0x7ffc060816d0, rv=0x7f8288ce18b0, cache=0x0) at core/rvalue.c:1854
#7  0x00005593f81b89ad in int_rve_defined (h=0x7ffc06082f80, msg=0x7f82890e0708, res=0x7ffc060816d0, rve=0x7f8288ce18a8) at core/rvalue.c:1890
#8  0x00005593f81b9fc4 in rval_expr_eval_int (h=0x7ffc06082f80, msg=0x7f82890e0708, res=0x7ffc060816d0, rve=0x7f8288ce2708) at core/rvalue.c:2113
#9  0x00005593f81ec024 in do_action (h=0x7ffc06082f80, a=0x7f8288ce5390, msg=0x7f82890e0708) at core/action.c:1047
#10 0x00005593f81fa61a in run_actions (h=0x7ffc06082f80, a=0x7f8288ce5390, msg=0x7f82890e0708) at core/action.c:1576
#11 0x00005593f81ec523 in do_action (h=0x7ffc06082f80, a=0x7f8288ce54e0, msg=0x7f82890e0708) at core/action.c:1062
#12 0x00005593f81fa61a in run_actions (h=0x7ffc06082f80, a=0x7f8288ce54e0, msg=0x7f82890e0708) at core/action.c:1576
#13 0x00005593f81e8aac in do_action (h=0x7ffc06082f80, a=0x7f8288ffa900, msg=0x7f82890e0708) at core/action.c:695
#14 0x00005593f81fa61a in run_actions (h=0x7ffc06082f80, a=0x7f8288ffa6c8, msg=0x7f82890e0708) at core/action.c:1576
#15 0x00005593f81fae2c in run_top_route (a=0x7f8288ffa6c8, msg=0x7f82890e0708, c=0x7ffc06082f80) at core/action.c:1661
#16 0x00007f828793a44d in reply_received (p_msg=0x7f82890e0708) at t_reply.c:2429
#17 0x00005593f82eb5f5 in do_forward_reply (msg=0x7f82890e0708, mode=0) at core/forward.c:763
#18 0x00005593f82ed46a in forward_reply (msg=0x7f82890e0708) at core/forward.c:864
#19 0x00005593f835b481 in receive_msg (
    buf=0x5593f8637640 <buf> "SIP/2.0 100 trying -- your call is important to us\r\nVia: SIP/2.0/UDP "..., len=529, rcv_info=0x7ffc06083520) at core/receive.c:509
#20 0x00005593f8232670 in udp_rcv_loop () at core/udp_server.c:554
#21 0x00005593f819a052 in main_loop () at main.c:1673
#22 0x00005593f81a343b in main (argc=9, argv=0x7ffc06083e68) at main.c:2802

(gdb) frame 0
#0  0x00005593f836b822 in match_by_name (avp=0xc, id=105, name=0x7ffc060813a8) at core/usr_avp.c:378
378	in core/usr_avp.c
(gdb) print avp
$3 = (avp_t *) 0xc
(gdb) print *avp
Cannot access memory at address 0xc

(gdb) frame 2
#2  0x00005593f836c02c in search_avp (ident=..., val=0x7ffc06081380, state=0x7ffc060813a0) at core/usr_avp.c:465
465	in core/usr_avp.c
(gdb) print list
$4 = (avp_list_t *) 0x7f8207bb25e0
(gdb) print *list
$5 = (avp_list_t) 0x7f821fff4c88
(gdb) print state->avp
$6 = (avp_t *) 0xc
(gdb) print state->name
$7 = {n = -2003544275, s = {s = 0x7f828894572d "lastdst)", len = 7}, re = 0x7f828894572d}
(gdb) print state->flags
$8 = 497
(gdb) info locals
ret = 0x18861c010
st = {flags = 273, id = 10, name = {n = -2000249939, s = {s = 0x7f8288c69bad "mapped_identity_user)", len = 20}, re = 0x7f8288c69bad}, avp = 0x7f823768ba60}
list = 0x7f8207bb25e0
__func__ = "search_avp"

(gdb) frame 4
#4  0x00007f82877df246 in pv_get_avp (msg=0x7f82890e0708, param=0x7f8288ce18d0, res=0x7ffc060814e0) at pv_core.c:1793
1793	pv_core.c: No such file or directory.
(gdb) info locals
name_type = 1
avp_name = {n = -2003544275, s = {s = 0x7f828894572d "lastdst)", len = 7}, re = 0x7f828894572d}
avp_value = {n = -128721111, s = {s = 0x5593f853df29 "", len = 0}, re = 0x5593f853df29}
avp = 0x7f8288dcec50
avp_value0 = {n = 0, s = {s = 0x0, len = -130631258}, re = 0x0}
avp0 = 0x7ffc06082f80
idx = 0
idxf = 0
p = 0x200000000 <error: Cannot access memory at address 0x200000000>
p_ini = 0x7f82890e0708 "/\031\232"
p_size = 21907
n = 0
state = {flags = 497, id = 105, name = {n = -2003544275, s = {s = 0x7f828894572d "lastdst)", len = 7}, re = 0x7f828894572d}, avp = 0xc}
__func__ = "pv_get_avp"

Question1: In frame 4, shouldn't "state" local variable be all 0's?
Question2: In frame 2, shouldn't "state->avp" have the value of "*list"?

Possible Solutions

I've seen there is a static declaration of "state" or "st" inside functions:

./src/modules/avp/avp.c:915:	static struct search_state state;
./src/core/usr_avp.c:421:         static struct search_state st;

Additional Information

• Kamailio Version - output of kamailio -v

version: kamailio 5.3.8 (x86_64/linux) 
flags: USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MMAP, PKG_MALLOC, Q_MALLOC, F_MALLOC, TLSF_MALLOC, DBG_SR_MEMORY, USE_FUTEX, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR, USE_DST_BLACKLIST, HAVE_RESOLV_RES, TLS_PTHREAD_MUTEX_SHARED
ADAPTIVE_WAIT_LOOPS 1024, MAX_RECV_BUFFER_SIZE 262144, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB
poll method support: poll, epoll_lt, epoll_et, sigio_rt, select.
id:  
compiled with gcc 8.3.0

• Operating System:

Debian 10

[miconda]

The avp search state is set inside pv_get_avp () before pv_core.c:1793, so the static state from core/usr_avp.c:421 is not used.

It looks like a race in the way that the current avp referred from the state is destroyed, so when the search reads ->next, the value is no longer valid. Do you have the sip traffic for this case, was there any other response processed at the same time? Or the transaction timed-out?

You can also check the config and see if/when the avp lastdst is deleted and try to see if you get any leads from there.

[smititelu]

Thank you very much for the feedback on this.

Unfortunately I don't have the full SIP for that callid, will definitely save it next time when/if it happens again.
Looking over the config, indeed there is a $avp(lastdst) call in onreply route but there is no "delete" for it throughout the whole config.

However, on that system, we are using tm module with (the new) "callid_cseq_matching" parameter set, which might lead to some transaction mismatching (and maybe to some transaction time-out?!)

I am closing this issue for now and will take this into consideration when/if it happens again.

Thanks,
Stefan