<!-- 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(a)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(a)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(a)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(a)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(a)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