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@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@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@192.168.86.250} <core> [core/receive.c:474]: receive_msg(): preparing to run routing scripts...
10(12) DEBUG: {1 1 ACK 1-39430@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@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@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@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@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@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@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@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@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@192.168.86.250} tm [t_lookup.c:981]: t_lookup_request(): no transaction found
10(12) DEBUG: {1 1 ACK 1-39430@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@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@192.168.86.250} <script>: >>>>>>> NOT MATCHED
10(12) exec: {1 1 ACK 1-39430@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@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@192.168.86.250} <core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
10(12) DEBUG: {1 1 ACK 1-39430@192.168.86.250} <core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
10(12) DEBUG: {1 1 ACK 1-39430@192.168.86.250} <core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
10(12) DEBUG: {1 1 ACK 1-39430@192.168.86.250} <core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
10(12) DEBUG: {1 1 ACK 1-39430@192.168.86.250} <core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
10(12) DEBUG: {1 1 ACK 1-39430@192.168.86.250} <core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
10(12) DEBUG: {1 1 ACK 1-39430@192.168.86.250} <core> [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil)
10(12) DEBUG: {1 1 ACK 1-39430@192.168.86.250} <core> [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil)
10(12) DEBUG: {1 1 ACK 1-39430@192.168.86.250} <core> [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil)
10(12) DEBUG: {1 1 ACK 1-39430@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@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@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@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@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 <bkaufman@bcmone.com> 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




 

SIP.US Client Support: 800.566.9810  |  SIPTRUNK Client Support: 800.250.6510  |  Flowroute Client Support: 855.356.9768
img
img
img
 

From: Alexis Fidalgo via sr-users <sr-users@lists.kamailio.org>
Sent: Monday, December 23, 2024 4:16 PM
To: Kamailio (SER) - Users Mailing List <sr-users@lists.kamailio.org>
Cc: Alexis Fidalgo <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)


> On 23 Dec 2024, at 6:49 PM, Alex Balashov via sr-users <sr-users@lists.kamailio.org> wrote:
>
> Look very carefully at how negative ACKs are handled here:
>
> https://nam11.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fkamailio%2Fkamailio%2Fblob%2Fmaster%2Fetc%2Fkamailio.cfg%23L716&data=05%7C02%7Cbkaufman%40bcmone.com%7C344d8fe5f8604da6709608dd23a04195%7Cafc1818e7b6848568913201b9396c4fc%7C1%7C0%7C638705893409762065%7CUnknown%7CTWFpbGZsb3d8eyJFbXB0eU1hcGkiOnRydWUsIlYiOiIwLjAuMDAwMCIsIlAiOiJXaW4zMiIsIkFOIjoiTWFpbCIsIldUIjoyfQ%3D%3D%7C0%7C%7C%7C&sdata=pWUV9HfUBdFYItGmXv9lpUOYmWXHJdrquEnfXWAl6Kg%3D&reserved=0
>
> -- Alex
>
>> On Dec 23, 2024, at 4:19 pm, Alexis Fidalgo via sr-users <sr-users@lists.kamailio.org> wrote:
>>
>> Hello all, moving just a bit aside of the http and async_http.
>>
>> After all the real useful and interesting thread on that topic what helped me, im facing a problem i cant deal with and need a hint at least.
>>
>> Scenario
>>
>> INVITE -> Kamailio
>>
>> on request_route
>> ...
>> if(is_method("INVITE")){
>> t_newtran();
>> http_async_query("http://nuc:8080", "HTTP_REPLY");
>> }
>> …
>>
>> Kamailio -> 100 - Trying
>>
>>
>> then
>>
>> 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");
>> t_reply(302,"Redirect");
>>   } else {
>>       xlog("L_INFO", "route[HTTP_REPLY]: error  $http_err)\n");
>>   }
>> }
>>
>> Kamailio -> 302 Redirect
>> ACK -> Kamailio
>>
>> This last ACK, how can i read it and use it to terminate the transaction? because Kamailio keeps transmitting the 302 message 3 more times until the transaction is finished by a timer
>>
>> 42(44) DEBUG: tm [t_reply.c:1723]: t_retransmit_reply(): reply retransmitted. buf=0x7f4c44f9d680: SIP/2.0 3..., shmem=0x7f4c3fce7900: SIP/2.0 3
>> 42(44) DEBUG: tm [t_reply.c:1723]: t_retransmit_reply(): reply retransmitted. buf=0x7f4c44f9d680: SIP/2.0 3..., shmem=0x7f4c3fce7900: SIP/2.0 3
>> 42(44) DEBUG: tm [t_reply.c:1723]: t_retransmit_reply(): reply retransmitted. buf=0x7f4c44f9d680: SIP/2.0 3..., shmem=0x7f4c3fce7900: SIP/2.0 3
>> 42(44) DEBUG: tm [timer.c:642]: wait_handler(): finished transaction: 0x7f4c3fcd35a0 (p:0x7f4c3fad85d0/n:0x7f4c3fad85d0)
>> 42(44) DEBUG: tm [h_table.c:133]: free_cell_helper(): freeing transaction 0x7f4c3fcd35a0 from timer.c:651
>>
>>
>> in request_route i have
>>
>> if(is_method("ACK")){
>> if(!t_check_trans()){
>> t_release();
>> }
>> exit;
>> }
>>
>>
>> __________________________________________________________
>> Kamailio - Users Mailing List - Non Commercial Discussions -- sr-users@lists.kamailio.org
>> To unsubscribe send an email to sr-users-leave@lists.kamailio.org
>> Important: keep the mailing list in the recipients, do not reply only to the sender!
>
> --
> Alex Balashov
> Principal Consultant
> Evariste Systems LLC
> Web: https://nam11.safelinks.protection.outlook.com/?url=https%3A%2F%2Fevaristesys.com%2F&data=05%7C02%7Cbkaufman%40bcmone.com%7C344d8fe5f8604da6709608dd23a04195%7Cafc1818e7b6848568913201b9396c4fc%7C1%7C0%7C638705893409783811%7CUnknown%7CTWFpbGZsb3d8eyJFbXB0eU1hcGkiOnRydWUsIlYiOiIwLjAuMDAwMCIsIlAiOiJXaW4zMiIsIkFOIjoiTWFpbCIsIldUIjoyfQ%3D%3D%7C0%7C%7C%7C&sdata=OjJMQi9y1SfE4Vkkbd58SiGGHACvEFYRohAxXKZaFW0%3D&reserved=0
> Tel: +1-706-510-6800
>
> __________________________________________________________
> Kamailio - Users Mailing List - Non Commercial Discussions -- sr-users@lists.kamailio.org
> To unsubscribe send an email to sr-users-leave@lists.kamailio.org
> Important: keep the mailing list in the recipients, do not reply only to the sender!

__________________________________________________________
Kamailio - Users Mailing List - Non Commercial Discussions -- sr-users@lists.kamailio.org
To unsubscribe send an email to sr-users-leave@lists.kamailio.org
Important: keep the mailing list in the recipients, do not reply only to the sender!