<p>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:</p>
<pre><code> UAC KAMAILIO UAS
--------------INVITE(1)------->
<--------------100(2)-------
--------------INVITE(3)------->
<--------------491(4)----------
--------------ACK(5)---------->
<--------------491(6)----------
--------------ACK(7)---------->
</code></pre>
<h3>Troubleshooting</h3>
<p>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.</p>
<h4>Reproduction</h4>
<p>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.</p>
<h4>Debugging Data</h4>
<p>This dump is generated with abort from the callback.</p>
<pre><code>#0 0x00007f6f16a77428 in __GI_raise (sig=sig@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@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@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@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@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"
</code></pre>
<h4>SIP Traffic</h4>
<pre><code>INVITE sip:49721555789@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@xxxxxxxxxxxx:5061>;tag=1
To: <sip:49721555789@xxxxxxxxxxxxx>
Call-ID: 1-4313@127.0.0.1
CSeq: 2 INVITE
Contact: sip:49721555789@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@xxxxxxxxxxxxxx:5061>;tag=1
To: <sip:49721555789@xxxxxxxxxxxxxxxxx>
Call-ID: 1-4313@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@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@xxxxxxxxxxxxxxxxxx:5061>;tag=1
To: <sip:49721555789@xxxxxxxxxxxxxxxxxxx>
Call-ID: 1-4313@127.0.0.1
CSeq: 2 INVITE
Contact: sip:49721555789@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@voip-test.1und1.de:5061>;tag=1
To: <sip:49721555789@voip-test.1und1.de>;tag=1
Call-ID: 1-4313@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@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@voip-test.1und1.de:5061>;tag=1
To: <sip:49721555789@voip-test.1und1.de>;tag=1
Call-ID: 1-4313@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
</code></pre>
<h3>Possible Solutions</h3>
<p>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.</p>
<h3>Additional Information</h3>
<ul>
<li><strong>Kamailio Version</strong> - output of <code>kamailio -v</code></li>
</ul>
<pre><code>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
</code></pre>
<ul>
<li><strong>Operating System</strong>:</li>
</ul>
<pre><code>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
</code></pre>
<p style="font-size:small;-webkit-text-size-adjust:none;color:#666;">—<br />You are receiving this because you are subscribed to this thread.<br />Reply to this email directly, <a href="https://github.com/kamailio/kamailio/issues/1871">view it on GitHub</a>, or <a href="https://github.com/notifications/unsubscribe-auth/AF36ZWDGkwxJoamgqQB2xXCvafL0lHMWks5vRmFPgaJpZM4bUOpg">mute the thread</a>.<img src="https://github.com/notifications/beacon/AF36ZbJTCUDiGscyvTFrDrrzcm4y7FMjks5vRmFPgaJpZM4bUOpg.gif" height="1" width="1" alt="" /></p>
<script type="application/json" data-scope="inboxmarkup">{"api_version":"1.0","publisher":{"api_key":"05dde50f1d1a384dd78767c55493e4bb","name":"GitHub"},"entity":{"external_key":"github/kamailio/kamailio","title":"kamailio/kamailio","subtitle":"GitHub repository","main_image_url":"https://github.githubassets.com/images/email/message_cards/header.png","avatar_image_url":"https://github.githubassets.com/images/email/message_cards/avatar.png","action":{"name":"Open in GitHub","url":"https://github.com/kamailio/kamailio"}},"updates":{"snippets":[{"icon":"DESCRIPTION","message":"Unwanted INVITE while using TMCB_ACK_NEG_IN callback (#1871)"}],"action":{"name":"View Issue","url":"https://github.com/kamailio/kamailio/issues/1871"}}}</script>
<script type="application/ld+json">[
{
"@context": "http://schema.org",
"@type": "EmailMessage",
"potentialAction": {
"@type": "ViewAction",
"target": "https://github.com/kamailio/kamailio/issues/1871",
"url": "https://github.com/kamailio/kamailio/issues/1871",
"name": "View Issue"
},
"description": "View this Issue on GitHub",
"publisher": {
"@type": "Organization",
"name": "GitHub",
"url": "https://github.com"
}
}
]</script>