<!-- 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@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"
```
#### 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@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
```
### 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
```
It seems to be a bug, indeed, that callback should be for receiving an ACK to negative response, as I could see in the comments from code.
I checked and that callback is not actually used anywhere in the code of other modules, so this was not noticed so far, on the other hand, even better, changing it won't affect anything existing at this moment, thus no worries to break something that relied on existing behaviour.
You can make a pull request for the fix, as you do development of the code using this callback type.
Closed #1871 via cd6ef63a1eb5951ccb38276a91e150187702b352.