[sr-dev] [kamailio/kamailio] Unwanted INVITE while using TMCB_ACK_NEG_IN callback (#1871)
Ionut Ionita
notifications at github.com
Wed Feb 27 11:43:27 CET 2019
<!--
Explain what you did, what you expected to happen, and what actually happened.
-->
I am trying to catch all messages belonging to a transaction in siptrace module. To achieve this I am registering TMCB_REQUEST_SENT, TMCB_RESPONSE_IN, TMCB_RESPONSE_SENT and TMCB_ACK_NEG_IN callbacks each time sip_trace() is called from the script. 2xx INVITE transactions are traced ok but I'm having issue in the following scenario:
UAC KAMAILIO UAS
--------------INVITE(1)------->
<--------------100(2)-------
--------------INVITE(3)------->
<--------------491(4)----------
--------------ACK(5)---------->
<--------------491(6)----------
--------------ACK(7)---------->
### Troubleshooting
As I said I am registering a callback for TMCB_ACK_NEG_IN and as expected message # 7 is traced, but the callback is also called once more, for message # 4 as I understand from the trace. After investigation, the place in tm from where the callback is called is t_reply.c:2290 in reply received, just after the ACK is sent to UAS.
#### Reproduction
<!--
If the issue can be reproduced, describe how it can be done.
-->
To reproduce the issue register a TMCB_ACK_NEG_IN in any kamailio module and create a scenario in which KAMAILIO will issue a hop-by-hop ACK.
#### Debugging Data
<!--
If you got a core dump, use gdb to extract troubleshooting data - full backtrace,
local variables and the list of the code at the issue location.
gdb /path/to/kamailio /path/to/corefile
bt full
info locals
list
If you are familiar with gdb, feel free to attach more of what you consider to
be relevant.
-->
This dump is generated with abort from the callback.
```
#0 0x00007f6f16a77428 in __GI_raise (sig=sig at entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
resultvar = 0
pid = 12031
selftid = 12031
#1 0x00007f6f16a7902a in __GI_abort () at abort.c:89
save_stage = 2
act = {__sigaction_handler = {sa_handler = 0x7becee, sa_sigaction = 0x7becee}, sa_mask = {__val = {
140114966526974, 140722638021392, 140115098302455, 140115090541944, 206158430256, 140722638021232,
140722638021008, 140722638021024, 18, 0, 12031, 8121608, 140115075184984, 0, 0, 34359738368}},
sa_flags = 248410608, sa_restorer = 0x0}
sigs = {__val = {32, 0 <repeats 15 times>}}
#2 0x00007f6f0ecc4c04 in trace_tm_neg_ack_in (t=0x7f6f0f1bcc68, type=4096, ps=0x7ffc8ad9e450) at siptrace.c:1466
__func__ = "trace_tm_neg_ack_in"
#3 0x00007f6f1542be24 in run_trans_callbacks_internal (cb_lst=0x7f6f0f1bcce0, type=4096, trans=0x7f6f0f1bcc68,
params=0x7ffc8ad9e450) at t_hooks.c:260
cbp = 0x7f6f0f1bc9f8
backup_from = 0xae6370 <def_list+16>
backup_to = 0xae6378 <def_list+24>
backup_dom_from = 0xae6380 <def_list+32>
backup_dom_to = 0xae6388 <def_list+40>
backup_uri_from = 0xae6360 <def_list>
backup_uri_to = 0xae6368 <def_list+8>
backup_xavps = 0xb2ea00 <_xavp_list_head>
__func__ = "run_trans_callbacks_internal"
#4 0x00007f6f1542c0d7 in run_trans_callbacks_off_params (type=4096, trans=0x7f6f0f1bcc68, p=0x7ffc8ad9e450)
at t_hooks.c:315
No locals.
#5 0x00007f6f153e1fb2 in reply_received (p_msg=0x7f6f1633c478) at t_reply.c:2291
msg_status = 491
last_uac_status = 0
ack = 0x7f6f0f1c0660 "ACK sip:49721555789 at 127.0.0.1:5062 SIP/2.0\r\nVia: SIP/2.0/UDP 127.0.0.1;branch=z9hG4bK625b.8be9496fad933213a6fef88939ddcf84.0\r\nFrom: freenet.testaccount.45 <sip:freenet.testaccount.45 at voip-test.test".---Type <return> to continue, or q <return> to quit---
..
ack_len = 343
branch = 0
reply_status = 3
onreply_route = 1
cancel_data = {cancel_bitmap = 0, reason = {cause = 0, u = {text = {s = 0x0, len = 7041898},
e2e_cancel = 0x0, packed_hdrs = {s = 0x0, len = 7041898}}}}
uac = 0x7f6f0f1bce78
t = 0x7f6f0f1bcc68
lack_dst = {send_sock = 0xa79a56 <buf+406>, to = {s = {sa_family = 39442,
sa_data = "\247\000\000\000\000\000\060\345ي\374\177\000"}, sin = {sin_family = 39442,
sin_port = 167, sin_addr = {s_addr = 0}, sin_zero = "0\345ي\374\177\000"}, sin6 = {
sin6_family = 39442, sin6_port = 167, sin6_flowinfo = 0, sin6_addr = {__in6_u = {
__u6_addr8 = "0\345ي\374\177\000\000\022\254k\000\000\000\000", __u6_addr16 = {58672, 35545,
32764, 0, 44050, 107, 0, 0}, __u6_addr32 = {2329535792, 32764, 7056402, 0}}},
sin6_scope_id = 8500896}}, id = 0, proto = -48 '\320', send_flags = {f = 5684, blst_imask = 32623}}
backup_user_from = 0x1
backup_user_to = 0x6
backup_domain_from = 0x7ffc8ad9e650
backup_domain_to = 0x7f6f16a977f7 <__fprintf+135>
backup_uri_from = 0xa79a0a <buf+330>
backup_uri_to = 0x4
backup_xavps = 0xa6008
replies_locked = 1
branch_ret = 0
prev_branch = 0
blst_503_timeout = 12031
hf = 0x6a00f4 <qm_info+46>
onsend_params = {req = 0x7f6f0f1beb30, rpl = 0x7f6f1633c478, param = 0x7f6f0f1bca08, code = -2, flags = 2,
branch = 0, t_rbuf = 0x7f6f0f1bce88, dst = 0x7f6f0f1bced8, send_buf = {
s = 0x7f6f0f1c0660 "ACK sip:49721555789 at 127.0.0.1:5062 SIP/2.0\r\nVia: SIP/2.0/UDP 127.0.0.1;branch=z9hG4bK625b.8be9496fad933213a6fef88939ddcf84.0\r\nFrom: freenet.testaccount.45 <sip:freenet.testaccount.45 at test---Type <return> to continue, or q <return> to quit---
"..., len = 343}}
ctx = {rec_lev = 10984022, run_flags = 0, last_retcode = 10983946, jmp_env = {{__jmpbuf = {32394306984,
140114718097409, 10984022, 10983954, 10983948, 7270476, 8500896, 4}, __mask_was_saved = 10983940,
__saved_mask = {__val = {1, 10983946, 6, 10983948, 7270406, 679888, 1064904, 1068184, 8, 70, 8121608,
10983948, 140115090286248, 10984022, 10983940, 140722638022224}}}}}
bctx = 0x3000000030
keng = 0x0
__func__ = "reply_received"
```
#### SIP Traffic
<!--
If the issue is exposed by processing specific SIP messages, grab them with ngrep or save in a pcap file, then add them next, or attach to issue, or provide a link to download them (e.g., to a pastebin site).
-->
```
INVITE sip:49721555789 at 127.0.0.1 SIP/2.0
Via: SIP/2.0/UDP 127.0.0.1:5061;branch=z9hG4bK-4313-1-0
From: freenet.testaccount.45 <sip:freenet.testaccount.45 at xxxxxxxxxxxx:5061>;tag=1
To: <sip:49721555789 at xxxxxxxxxxxxx>
Call-ID: 1-4313 at 127.0.0.1
CSeq: 2 INVITE
Contact: sip:49721555789 at 127.0.0.1:5061
Max-Forwards: 70
Content-Length: 0
X-Siptrace-Fromip: udp:127.0.0.1:5061
X-Siptrace-Toip: udp:127.0.0.1:5060
X-Siptrace-Time: 1551199601 871170
X-Siptrace-Method: INVITE
X-Siptrace-Dir: in
SIP/2.0 100 trying -- your call is important to us
Via: SIP/2.0/UDP 127.0.0.1:5061;branch=z9hG4bK-4313-1-0
From: freenet.testaccount.45 <sip:freenet.testaccount.45 at xxxxxxxxxxxxxx:5061>;tag=1
To: <sip:49721555789 at xxxxxxxxxxxxxxxxx>
Call-ID: 1-4313 at 127.0.0.1
CSeq: 2 INVITE
Server: kamailio (5.3.0-dev2 (x86_64/linux))
Content-Length: 0
X-Siptrace-Fromip: udp:127.0.0.1:5060
X-Siptrace-Toip: udp:127.0.0.1:5061
X-Siptrace-Time: 1551199601 871872
X-Siptrace-Method: INVITE
X-Siptrace-Dir: out
INVITE sip:49721555789 at 127.0.0.1:5062 SIP/2.0
Record-Route: <sip:127.0.0.1;lr;did=959.7082>
Via: SIP/2.0/UDP 127.0.0.1;branch=z9hG4bKd89f.a1985a4b6648b7b274edce82de763f18.0
Via: SIP/2.0/UDP 127.0.0.1:5061;branch=z9hG4bK-4313-1-0
From: freenet.testaccount.45 <sip:freenet.testaccount.45 at xxxxxxxxxxxxxxxxxx:5061>;tag=1
To: <sip:49721555789 at xxxxxxxxxxxxxxxxxxx>
Call-ID: 1-4313 at 127.0.0.1
CSeq: 2 INVITE
Contact: sip:49721555789 at 127.0.0.1:5061
Max-Forwards: 69
Content-Length: 0
X-Siptrace-Fromip: udp:127.0.0.1:5060
X-Siptrace-Toip: udp:127.0.0.1:5062
X-Siptrace-Time: 1551199601 872145
X-Siptrace-Method: INVITE
X-Siptrace-Dir: out
SIP/2.0 491 Irgendwas1
Via: SIP/2.0/UDP 127.0.0.1;branch=z9hG4bKd89f.a1985a4b6648b7b274edce82de763f18.0, SIP/2.0/UDP 127.0.0.1:5061;branch=z9hG4bK-4313-1-0
From: freenet.testaccount.45 <sip:freenet.testaccount.45 at voip-test.1und1.de:5061>;tag=1
To: <sip:49721555789 at voip-test.1und1.de>;tag=1
Call-ID: 1-4313 at 127.0.0.1
CSeq: 2 INVITE
Contact: <sip:127.0.0.1:5062;transport=UDP>
Content-Length: 0
X-Siptrace-Fromip: udp:127.0.0.1:5062
X-Siptrace-Toip: udp:127.0.0.1:5060
X-Siptrace-Time: 1551199601 872350
X-Siptrace-Method: INVITE
X-Siptrace-Dir: in
ACK sip:49721555789 at 127.0.0.1:5062 SIP/2.0
Via: SIP/2.0/UDP 127.0.0.1;branch=z9hG4bKd89f.a1985a4b6648b7b274edce82de763f18.0
From: freenet.testaccount.45 <sip:freenet.testaccount.45 at voip-test.1und1.de:5061>;tag=1
To: <sip:49721555789 at voip-test.1und1.de>;tag=1
Call-ID: 1-4313 at 127.0.0.1
CSeq: 2 ACK
Max-Forwards: 69
Content-Length: 0
X-Siptrace-Fromip: udp:127.0.0.1:5060
X-Siptrace-Toip: udp:127.0.0.1:5062
X-Siptrace-Time: 1551199601 872417
X-Siptrace-Method: ACK
X-Siptrace-Dir: out
```
### Possible Solutions
I think the solution is to avoid calling these callbacks from that location, since the callback is called TMCB_ACK_NEG_IN not NEG_OUT.
### Additional Information
* **Kamailio Version** - output of `kamailio -v`
```
version: kamailio 5.3.0-dev2 (x86_64/linux) 5bd547-dirty
flags: STATS: Off, 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
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: 5bd547 -dirty
compiled on 16:25:01 Feb 26 2019 with gcc 5.4.0
```
* **Operating System**:
<!--
Details about the operating system, the type: Linux (e.g.,: Debian 8.4, Ubuntu 16.04, CentOS 7.1, ...), MacOS, xBSD, Solaris, ...;
Kernel details (output of `uname -a`)
-->
```
Linux DXBU-FVC2J42 4.10.0-38-generic #42~16.04.1-Ubuntu SMP Tue Oct 10 16:32:20 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
```
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/1871
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/sr-dev/attachments/20190227/fbfa0c78/attachment-0001.html>
More information about the sr-dev
mailing list