[SR-Users] Re: help on how to get ACK

IF the transaction was finished, then yes, but: 10(12) DEBUG: {1 1 ACK 1-39430(a)192.168.86.250} tm [t_lookup.c:781]: t_lookup_request(): start searching: hash=48094, isACK=1 10(12) DEBUG: {1 1 ACK 1-39430(a)192.168.86.250} tm [t_lookup.c:499]: matching_3261(): RFC3261 transaction matching failed - via branch [z9hG4bK-39430-1-3] 10(12) DEBUG: {1 1 ACK 1-39430(a)192.168.86.250} tm [t_lookup.c:981]: t_lookup_request(): no transaction found Kaufman Senior Voice Engineer E: bkaufman(a)bcmone.com SIP.US Client Support: 800.566.9810 | SIPTRUNK Client Support: 800.250.6510 | Flowroute Client Support: 855.356.9768 [img]<https://www.sip.us/> [img]<https://www.siptrunk.com/> [img]<https://www.flowroute.com/> ________________________________ From: Alexis Fidalgo &lt;alzrck(a)gmail.com&gt; Sent: Monday, December 23, 2024 4:49 PM To: Ben Kaufman &lt;bkaufman(a)bcmone.com&gt; Cc: Kamailio (SER) - Users Mailing List &lt;sr-users(a)lists.kamailio.org&gt; Subject: Re: [SR-Users] help on how to get ACK CAUTION: This email originated from outside the organization. Do not click links or open attachments unless you recognize the sender and know the content is safe. sorry about the log (changed now). my question is, if script execution is finished, the associated transaction (red part) isnt ended too? 10(12) DEBUG: <core> [core/udp_server.c:707]: udp_rcv_loop(): received on udp socket: (106/100/412) [[ACK sip:1111@otherdomain.com:5060 SIP/2.0 0D 0A Via: SIP/2.0/UDP 192.168.86.250:5060;branch=z9hG4bK-39430]] 10(12) DEBUG: <core> [core/parser/parse_fline.c:247]: parse_first_line(): first line type 1 (request) flags 1 10(12) DEBUG: <core> [core/parser/msg_parser.c:722]: parse_msg(): SIP Request: 10(12) DEBUG: <core> [core/parser/msg_parser.c:723]: parse_msg(): method: <ACK> 10(12) DEBUG: <core> [core/parser/msg_parser.c:725]: parse_msg(): uri: <sip:1111@otherdomain.com:5060> 10(12) DEBUG: <core> [core/parser/msg_parser.c:727]: parse_msg(): version: <SIP/2.0> 10(12) DEBUG: <core> [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Via] type 1 10(12) DEBUG: <core> [core/parser/parse_via.c:1309]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-39430-1-3>; state=16 10(12) DEBUG: <core> [core/parser/parse_via.c:2663]: parse_via(): end of header reached, state=5 10(12) DEBUG: <core> [core/parser/msg_parser.c:592]: parse_headers(): Via found, flags=2 10(12) DEBUG: <core> [core/parser/msg_parser.c:594]: parse_headers(): this is the first via 10(12) DEBUG: <core> [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [From] type 4 10(12) DEBUG: <core> [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [To] type 3 10(12) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=a6a1c5f60faecf035a1ae5b6e96e979a-e94a2550 10(12) DEBUG: <core> [core/parser/parse_addr_spec.c:904]: parse_addr_spec(): end of header reached, state=29 10(12) DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): <To> [87]; uri=[sip:123456@192.168.86.128:5060] 10(12) DEBUG: <core> [core/parser/msg_parser.c:174]: get_hdr_field(): to body (39)[123456 <sip:123456@192.168.86.128:5060>], to tag (41)[a6a1c5f60faecf035a1ae5b6e96e979a-e94a2550] 10(12) DEBUG: <core> [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Call-ID] type 6 10(12) DEBUG: <core> [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [CSeq] type 5 10(12) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <ACK> 10(12) DEBUG: <core> [core/receive.c:392]: receive_msg(): --- received sip message - request - call-id: [1-39430(a)192.168.86.250] - cseq: [1 ACK] 10(12) DEBUG: <core> [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Contact] type 7 10(12) DEBUG: <core> [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Max-Forwards] type 8 10(12) DEBUG: <core> [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Subject] type 27 10(12) DEBUG: <core> [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Content-Length] type 12 10(12) DEBUG: <core> [core/parser/msg_parser.c:187]: get_hdr_field(): content_length=0 10(12) DEBUG: <core> [core/parser/msg_parser.c:91]: get_hdr_field(): found end of header 10(12) DEBUG: {1 1 ACK 1-39430(a)192.168.86.250} <core> [core/receive.c:263]: ksr_evrt_pre_routing(): event route core:pre-routing not defined 10(12) DEBUG: {1 1 ACK 1-39430(a)192.168.86.250} <core> [core/receive.c:474]: receive_msg(): preparing to run routing scripts... 10(12) DEBUG: {1 1 ACK 1-39430(a)192.168.86.250} sl [sl_funcs.c:455]: sl_filter_ACK(): too late to be a local ACK! 10(12) exec: {1 1 ACK 1-39430(a)192.168.86.250} *** cfgtrace:dbg_cfg_trace(): request_route=[DEFAULT_ROUTE] c=[/etc/kamailio/kamailio.cfg] l=537 a=5 n=route 10(12) exec: {1 1 ACK 1-39430(a)192.168.86.250} *** cfgtrace:dbg_cfg_trace(): request_route=[AF_SL] c=[/etc/kamailio/kamailio.cfg] l=625 a=16 n=if 10(12) exec: {1 1 ACK 1-39430(a)192.168.86.250} *** cfgtrace:dbg_cfg_trace(): request_route=[AF_SL] c=[/etc/kamailio/kamailio.cfg] l=617 a=25 n=is_method 10(12) exec: {1 1 ACK 1-39430(a)192.168.86.250} *** cfgtrace:dbg_cfg_trace(): request_route=[AF_SL] c=[/etc/kamailio/kamailio.cfg] l=623 a=16 n=if 10(12) exec: {1 1 ACK 1-39430(a)192.168.86.250} *** cfgtrace:dbg_cfg_trace(): request_route=[AF_SL] c=[/etc/kamailio/kamailio.cfg] l=618 a=24 n=t_check_trans 10(12) DEBUG: {1 1 ACK 1-39430(a)192.168.86.250} tm [t_lookup.c:1565]: t_check_msg(): msg (0x7f05de39d4d0) id=1/12 global id=0/0 T start=0xffffffffffffffff 10(12) DEBUG: {1 1 ACK 1-39430(a)192.168.86.250} tm [t_lookup.c:781]: t_lookup_request(): start searching: hash=48094, isACK=1 10(12) DEBUG: {1 1 ACK 1-39430(a)192.168.86.250} tm [t_lookup.c:499]: matching_3261(): RFC3261 transaction matching failed - via branch [z9hG4bK-39430-1-3] 10(12) DEBUG: {1 1 ACK 1-39430(a)192.168.86.250} tm [t_lookup.c:981]: t_lookup_request(): no transaction found 10(12) DEBUG: {1 1 ACK 1-39430(a)192.168.86.250} tm [t_lookup.c:1637]: t_check_msg(): msg (0x7f05de39d4d0) id=1/12 global id=1/12 T end=(nil) 10(12) exec: {1 1 ACK 1-39430(a)192.168.86.250} *** cfgtrace:dbg_cfg_trace(): request_route=[AF_SL] c=[/etc/kamailio/kamailio.cfg] l=619 a=26 n=xlog 10(12) INFO: {1 1 ACK 1-39430(a)192.168.86.250} <script>: >>>>>>> NOT MATCHED 10(12) exec: {1 1 ACK 1-39430(a)192.168.86.250} *** cfgtrace:dbg_cfg_trace(): request_route=[AF_SL] c=[/etc/kamailio/kamailio.cfg] l=620 a=2 n=exit 10(12) DEBUG: {1 1 ACK 1-39430(a)192.168.86.250} <core> [core/receive.c:531]: receive_msg(): request-route executed in: 183 usec 10(12) DEBUG: {1 1 ACK 1-39430(a)192.168.86.250} <core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil) 10(12) DEBUG: {1 1 ACK 1-39430(a)192.168.86.250} <core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil) 10(12) DEBUG: {1 1 ACK 1-39430(a)192.168.86.250} <core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil) 10(12) DEBUG: {1 1 ACK 1-39430(a)192.168.86.250} <core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil) 10(12) DEBUG: {1 1 ACK 1-39430(a)192.168.86.250} <core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil) 10(12) DEBUG: {1 1 ACK 1-39430(a)192.168.86.250} <core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil) 10(12) DEBUG: {1 1 ACK 1-39430(a)192.168.86.250} <core> [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil) 10(12) DEBUG: {1 1 ACK 1-39430(a)192.168.86.250} <core> [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil) 10(12) DEBUG: {1 1 ACK 1-39430(a)192.168.86.250} <core> [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil) 10(12) DEBUG: {1 1 ACK 1-39430(a)192.168.86.250} <core> [core/receive.c:635]: receive_msg(): cleaning up 42(44) DEBUG: tm [t_reply.c:1723]: t_retransmit_reply(): reply retransmitted. buf=0x7f05de0f5680: SIP/2.0 3..., shmem=0x7f05d8e56900: SIP/2.0 3 42(44) DEBUG: tm [t_reply.c:1723]: t_retransmit_reply(): reply retransmitted. buf=0x7f05de0f5680: SIP/2.0 3..., shmem=0x7f05d8e56900: SIP/2.0 3 42(44) DEBUG: tm [t_reply.c:1723]: t_retransmit_reply(): reply retransmitted. buf=0x7f05de0f5680: SIP/2.0 3..., shmem=0x7f05d8e56900: SIP/2.0 3 42(44) DEBUG: tm [timer.c:642]: wait_handler(): finished transaction: 0x7f05d8e425a0 (p:0x7f05d8d75870/n:0x7f05d8d75870) 42(44) DEBUG: tm [h_table.c:133]: free_cell_helper(): freeing transaction 0x7f05d8e425a0 from timer.c:651 request_route if(is_method("ACK")){ if(!t_check_trans()){ xlog("L_INFO",">>>>>>> NOT MATCHED\n"); exit; } else { xlog("L_INFO",">>>>>>> MATCHED\n"); } } if(is_method("INVITE")){ t_newtran(); http_async_query("http://nuc:8080", "HTTP_REPLY"); } route[HTTP_REPLY] { if ($http_ok) { xlog("L_INFO", "route[HTTP_REPLY]: status $http_rs\n"); xlog("L_INFO", "route[HTTP_REPLY]: body $http_rb\n"); remove_hf("Contact"); append_branch("sip:1111@otherdomain.com:5060"); t_reply(302,"Redirect"); } else { xlog("L_INFO", "route[HTTP_REPLY]: error $http_err)\n"); } } sipp xml <?xml version="1.0" encoding="ISO-8859-1" ?> <!DOCTYPE scenario SYSTEM "sipp.dtd"> <scenario name="Basic Sipstone UAC"> <!-- In client mode (sipp placing calls), the Call-ID MUST be --> <!-- generated by sipp. To do so, use [call_id] keyword. --> <send retrans="500"> <![CDATA[ INVITE sip:[service]@[remote_ip]:[remote_port] SIP/2.0 Via: SIP/2.0/[transport] [local_ip]:[local_port];branch=[branch] From: sipp <sip:sipp@[local_ip]:[local_port]>;tag=[pid]SIPpTag00[call_number] To: [service] <sip:[service]@[remote_ip]:[remote_port]> Call-ID: [call_id] CSeq: 1 INVITE Contact: sip:sipp@[local_ip]:[local_port] Max-Forwards: 70 Subject: Performance Test Content-Type: application/sdp Content-Length: [len] v=0 o=user1 53655765 2353687637 IN IP[local_ip_type] [local_ip] s=- c=IN IP[media_ip_type] [media_ip] t=0 0 m=audio [media_port] RTP/AVP 0 a=rtpmap:0 PCMU/8000 ]]> </send> <recv response="100" optional="true"></recv> <!-- By adding rrs="true" (Record Route Sets), the route sets --> <!-- are saved and used for following messages sent. Useful to test --> <!-- against stateful SIP proxies/B2BUAs. --> <recv response="302" rrs="true" rtd="true"> </recv> <!-- Packet lost can be simulated in any send/recv message by --> <!-- by adding the 'lost = "10"'. Value can be [1-100] percent. --> <send> <![CDATA[ ACK [next_url] SIP/2.0 Via: SIP/2.0/[transport] [local_ip]:[local_port];branch=[branch] From: sipp <sip:sipp@[local_ip]:[local_port]>;tag=[pid]SIPpTag00[call_number] To: [service] <sip:[service]@[remote_ip]:[remote_port]>[peer_tag_param] Call-ID: [call_id] CSeq: 1 ACK Contact: [next_url] Max-Forwards: 70 Subject: Performance Test Content-Length: 0 ]]> </send> <!-- definition of the response time repartition table (unit is ms) --> <ResponseTimeRepartition value="10, 20, 30, 40, 50, 100, 150, 200"/> <!-- definition of the call length repartition table (unit is ms) --> <CallLengthRepartition value="10, 50, 100, 500, 1000, 5000, 10000"/> </scenario> pcap list 22 603.965446646 192.168.86.250 → 192.168.86.128 SIP/SDP 588 Request: INVITE sip:123456@192.168.86.128:5060 | 23 603.966309968 192.168.86.128 → 192.168.86.250 SIP 344 Status: 100 Trying | 24 604.271008247 192.168.86.128 → 192.168.86.250 SIP 434 Status: 302 Redirect | 25 604.389939182 192.168.86.250 → 192.168.86.128 SIP 454 Request: ACK sip:1111@otherdomain.com:5060 | 26 604.760536760 192.168.86.128 → 192.168.86.250 SIP 434 Status: 302 Redirect | 27 605.760472746 192.168.86.128 → 192.168.86.250 SIP 434 Status: 302 Redirect | 28 607.760461967 192.168.86.128 → 192.168.86.250 SIP 434 Status: 302 Redirect | sipp trace output ----------------------------------------------- 2024-12-23 19:45:32.343458 UDP message sent (546 bytes): INVITE sip:123456@192.168.86.128:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.86.250:5060;branch=z9hG4bK-39430-1-0 From: sipp <sip:sipp@192.168.86.250:5060>;tag=39430SIPpTag001 To: 123456 <sip:123456@192.168.86.128:5060> Call-ID: 1-39430(a)192.168.86.250 CSeq: 1 INVITE Contact: sip:sipp@192.168.86.250:5060 Max-Forwards: 70 Subject: Performance Test Content-Type: application/sdp Content-Length: 139 v=0 o=user1 53655765 2353687637 IN IP4 192.168.86.250 s=- c=IN IP4 192.168.86.250 t=0 0 m=audio 6000 RTP/AVP 0 a=rtpmap:0 PCMU/8000 ----------------------------------------------- 2024-12-23 19:45:32.522315 UDP message received [302] bytes : SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.86.250:5060;branch=z9hG4bK-39430-1-0 From: sipp <sip:sipp@192.168.86.250:5060>;tag=39430SIPpTag001 To: 123456 <sip:123456@192.168.86.128:5060> Call-ID: 1-39430(a)192.168.86.250 CSeq: 1 INVITE Server: kamailio (5.8.4 (x86_64/linux)) Content-Length: 0 ----------------------------------------------- 2024-12-23 19:45:32.934151 UDP message received [392] bytes : SIP/2.0 302 Redirect Via: SIP/2.0/UDP 192.168.86.250:5060;branch=z9hG4bK-39430-1-0 From: sipp <sip:sipp@192.168.86.250:5060>;tag=39430SIPpTag001 To: 123456 <sip:123456@192.168.86.128:5060>;tag=a6a1c5f60faecf035a1ae5b6e96e979a-e94a2550 Call-ID: 1-39430(a)192.168.86.250 CSeq: 1 INVITE Contact: <sip:1111@otherdomain.com:5060> Server: kamailio (5.8.4 (x86_64/linux)) Content-Length: 0 ----------------------------------------------- 2024-12-23 19:45:32.935234 UDP message sent (412 bytes): ACK sip:1111@otherdomain.com:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.86.250:5060;branch=z9hG4bK-39430-1-3 From: sipp <sip:sipp@192.168.86.250:5060>;tag=39430SIPpTag001 To: 123456 <sip:123456@192.168.86.128:5060>;tag=a6a1c5f60faecf035a1ae5b6e96e979a-e94a2550 Call-ID: 1-39430(a)192.168.86.250 CSeq: 1 ACK Contact: sip:1111@otherdomain.com:5060 Max-Forwards: 70 Subject: Performance Test Content-Length: 0 On 23 Dec 2024, at 7:28 PM, Ben Kaufman &lt;bkaufman(a)bcmone.com&gt; wrote: Which log line do you get? Also note that both of your log lines say "Matched transaction", but the condition is negated (it starts with an exclamation mark). Also refer to the documentation for the function to see what happens when the ACK for a negative reply is matched. https://kamailio.org/docs/modules/5.8.x/modules/tm#tm.f.t_check_trans Kaufman Senior Voice Engineer E: bkaufman@bcmone.com<mailto:bkaufman@bcmone.com> SIP.US Client Support: 800.566.9810 | SIPTRUNK Client Support: 800.250.6510 | Flowroute Client Support: 855.356.9768 [img]<https://www.sip.us/> [img]<https://www.siptrunk.com/> [img]<https://www.flowroute.com/> ________________________________ From: Alexis Fidalgo via sr-users <sr-users@lists.kamailio.org<mailto:sr-users@lists.kamailio.org>> Sent: Monday, December 23, 2024 4:16 PM To: Kamailio (SER) - Users Mailing List <sr-users@lists.kamailio.org<mailto:sr-users@lists.kamailio.org>> Cc: Alexis Fidalgo <alzrck@gmail.com<mailto:alzrck@gmail.com>> Subject: [SR-Users] Re: help on how to get ACK CAUTION: This email originated from outside the organization. Do not click links or open attachments unless you recognize the sender and know the content is safe. Yes, i’ve been reading it when you mentioned the loose_route and has_totag() in a previous email. if(is_method("ACK")){ if(!t_check_trans()){ xlog("L_INFO","AAAA: MATCHED TRANSACTION\n"); } else { xlog("L_INFO","BBBB: MATCHED TRANSACTION\n"); } exit; } (moving the exit; inside the else has same effect on my test) __________________________________________________________ Kamailio - Users Mailing List - Non Commercial Discussions -- sr-users@lists.kamailio.org<mailto:sr-users@lists.kamailio.org> To unsubscribe send an email to sr-users-leave@lists.kamailio.org<mailto:sr-users-leave@lists.kamailio.org> Important: keep the mailing list in the recipients, do not reply only to the sender!