Hello
I use the ‘tm.t_uac_start’ function to send an INVITE and then the ‘tm.cancel’ function to cancel the INVITE.
But the ‘tm.cancel’ function immediately deletes the transaction. Kamailio can't acknowledge message 487 because the transaction has been deleted.

Callflow description:

‘tm.t_uac_start’
Kamailio: INVITE --->
Kamailio: <--- 180 Ringing
'tm.cancel'
Kamailio: CANCEL --->
Kamailio: <--- 200 OK (CANCEL)
Kamailio: <--- 487 Request Terminated (INVITE)
Kamailio can't send "ACK" because the transaction has been deleted

Below trace:

21(45279) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: exec is str: {"params":["INVITE","sip:2345@sip.osp.com","sip:10.192.117.5:5049","udp:10.192.117.6:5084","From: sip:+336111111111@fqfn-incoming.com;tag=a5507eec786ec44a0aa7ec48e98248e4\r\nTo: sip:2345@sip.osp.com\r\nCSeq: 1 INVITE\r\nCall-ID: 68443192-0f66b617ce5917df\r\nContact: sip:Kasuar@10.192.117.6:5084\r\nContent-Type: application/sdp\r\nSupported: gruu,replaces,norefersub\r\nAllow: INVITE,ACK,BYE,CANCEL,OPTIONS,NOTIFY,SUBSCRIBE,INFO,MESSAGE,UPDATE,REFER\r\nUser-Agent: tm.cancel\r\n","v=0\r\no=- 3218051986 1337943000 IN IP4 10.192.117.5\r\ns=-\r\nc=IN IP4 10.192.117.5\r\nt=0 0\r\nm=audio 5936 RTP/AVP 0 8 101\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:8 PCMA/8000\r\na=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-15\r\na=sendrecv\r\na=rtcp-rsize\r\na=ssrc:2797071403 cname:sip:1234@sip.osp.com\r\na=mid:0\r\na=minptime:20\r\na=ptime:20\r\na=label:1\r\n"],"jsonrpc":"2.0","method":"tm.t_uac_start","id":1}
21(45279) DEBUG: [core/socket_info.c:740]: grep_sock_info(): checking if host==us: 12==12 && [10.192.117.6] == [10.192.117.6]
21(45279) DEBUG: [core/socket_info.c:744]: grep_sock_info(): checking if port 5084 (advertise 0) matches port 5084
21(45279) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [From] type 4
21(45279) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [To] type 3
21(45279) DEBUG: [core/parser/parse_addr_spec.c:904]: parse_addr_spec(): end of header reached, state=10
21(45279) DEBUG: [core/parser/msg_parser.c:172]: get_hdr_field(): [24]; uri=[sip:2345@sip.osp.com]
21(45279) DEBUG: [core/parser/msg_parser.c:174]: get_hdr_field(): to body (24)[sip:2345@sip.osp.com
], to tag (0)[]

3(45261) INFO: <script>: 2024-10-31 10-54-06 [debug] /opt/kamailio/callbasic.lua:154: COMMANDE {"jsonrpc":"2.0","method":"tm.cancel","id":1,"params":["68443192-0f66b617ce5917df","1"]}
3(45261) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: exec is str: {"jsonrpc":"2.0","method":"tm.cancel","id":1,"params":["68443192-0f66b617ce5917df","1"]}
3(45261) DEBUG: tm [t_lookup.c:2285]: t_lookup_callid(): just locked hash index 43770, looking for transactions there:
3(45261) DEBUG: tm [t_lookup.c:2310]: t_lookup_callid(): we have a match: callid=>>Call-ID: 68443192-0f66b617ce5917df
<< cseq=>>CSeq: 1<<
3(45261) DEBUG: tm [t_lookup.c:2317]: t_lookup_callid(): t_lookup_callid: transaction found.
3(45261) DEBUG: tm [t_cancel.c:427]: rpc_cancel(): Now calling cancel_uacs
3(45261) DEBUG: tm [t_cancel.c:337]: cancel_branch(): sending cancel...
3(45261) DEBUG: [core/parser/parse_fline.c:247]: parse_first_line(): first line type 1 (request) flags 1
3(45261) DEBUG: [core/parser/msg_parser.c:722]: parse_msg(): SIP Request:
3(45261) DEBUG: [core/parser/msg_parser.c:723]: parse_msg(): method:
3(45261) DEBUG: [core/parser/msg_parser.c:725]: parse_msg(): uri: sip:2345@sip.osp.com
3(45261) DEBUG: [core/parser/msg_parser.c:727]: parse_msg(): version: <SIP/2.0>
3(45261) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Via] type 1
3(45261) DEBUG: [core/parser/parse_via.c:1309]: parse_via_param(): Found param type 232, = <z9hG4bKafaa.fe4571d3000000000000000000000000.0>; state=16
3(45261) DEBUG: [core/parser/parse_via.c:2663]: parse_via(): end of header reached, state=5
3(45261) DEBUG: [core/parser/msg_parser.c:592]: parse_headers(): Via found, flags=2
3(45261) DEBUG: [core/parser/msg_parser.c:594]: parse_headers(): this is the first via
3(45261) DEBUG: app_lua [app_lua_api.c:511]: sr_lua_reload_script(): No need to reload [/opt/kamailio/kamailio.lua] is version 0
3(45261) DEBUG: app_lua [app_lua_api.c:688]: app_lua_run_ex(): executing Lua function: [[ksr_tm_event]]
3(45261) DEBUG: app_lua [app_lua_api.c:690]: app_lua_run_ex(): lua top index is: 1
3(45261) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: xinfo is str: 2024-10-31 10-54-06 [debug] /opt/kamailio/kamailio.lua:143: --> Sending request: $rm

3(45261) DEBUG: [core/pvapi.c:410]: pv_cache_lookup(): pvar [$rm] found in cache
3(45261) INFO: <script>: 2024-10-31 10-54-06 [debug] /opt/kamailio/kamailio.lua:143: --> Sending request: CANCEL
3(45261) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $hdr(Hexarb)
3(45261) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $hdr(Hexarb)
3(45261) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Hexarb] type 0
3(45261) DEBUG: [core/pvapi.c:386]: pv_cache_add(): pvar [$hdr(Hexarb)] added in cache
3(45261) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [To] type 3
3(45261) DEBUG: [core/parser/parse_addr_spec.c:904]: parse_addr_spec(): end of header reached, state=10
3(45261) DEBUG: [core/parser/msg_parser.c:172]: get_hdr_field(): [24]; uri=[sip:2345@sip.osp.com]
3(45261) DEBUG: [core/parser/msg_parser.c:174]: get_hdr_field(): to body (24)[sip:2345@sip.osp.com
], to tag (0)[]
3(45261) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [From] type 4
3(45261) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [CSeq] type 5
3(45261) DEBUG: [core/parser/msg_parser.c:152]: get_hdr_field(): cseq : <1>
3(45261) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Call-ID] type 6
3(45261) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Max-Forwards] type 8
3(45261) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Content-Length] type 12
3(45261) DEBUG: [core/parser/msg_parser.c:187]: get_hdr_field(): content_length=0
3(45261) DEBUG: [core/parser/msg_parser.c:91]: get_hdr_field(): found end of header
3(45261) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Via] type 1
3(45261) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Hexarb] type 0
3(45261) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [To] type 3
3(45261) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Hexarb] type 0
3(45261) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [From] type 4
3(45261) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Hexarb] type 0
3(45261) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [CSeq] type 5
3(45261) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Hexarb] type 0
3(45261) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Call-ID] type 6
3(45261) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Hexarb] type 0
3(45261) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Max-Forwards] type 8
3(45261) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Hexarb] type 0
3(45261) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Content-Length] type 12
3(45261) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Hexarb] type 0
3(45261) DEBUG: app_lua [app_lua_mod.c:166]: sr_kemi_config_engine_lua(): execution of route type 513 with name [ksr_tm_event] returned 1
3(45261) DEBUG: jsonrpcs [jsonrpcs_mod.c:443]: jsonrpc_send_mode(): sending response with body: (nil) - 200 OK
4(45262) DEBUG: [core/udp_server.c:715]: udp_rcv_loop(): received on udp socket: (106/100/329) [[SIP/2.0 200 OK 0D 0A Via: SIP/2.0/UDP 10.192.117.6:5084;branch=z9hG4bKafaa.fe4571d30000000000000000000000]]
4(45262) DEBUG: [core/parser/parse_fline.c:247]: parse_first_line(): first line type 2 (reply(status)) flags 1
4(45262) DEBUG: [core/parser/msg_parser.c:732]: parse_msg(): SIP Reply (status):
4(45262) DEBUG: [core/parser/msg_parser.c:733]: parse_msg(): version: <SIP/2.0>
4(45262) DEBUG: [core/parser/msg_parser.c:735]: parse_msg(): status: <200>
4(45262) DEBUG: [core/parser/msg_parser.c:737]: parse_msg(): reason:
4(45262) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Via] type 1
4(45262) DEBUG: [core/parser/parse_via.c:1309]: parse_via_param(): Found param type 232, = <z9hG4bKafaa.fe4571d3000000000000000000000000.0>; state=16
4(45262) DEBUG: [core/parser/parse_via.c:2663]: parse_via(): end of header reached, state=5
4(45262) DEBUG: [core/parser/msg_parser.c:592]: parse_headers(): Via found, flags=2
4(45262) DEBUG: [core/parser/msg_parser.c:594]: parse_headers(): this is the first via
4(45262) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [To] type 3
4(45262) DEBUG: [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=501b95048bf50805
4(45262) DEBUG: [core/parser/parse_addr_spec.c:904]: parse_addr_spec(): end of header reached, state=29
4(45262) DEBUG: [core/parser/msg_parser.c:172]: get_hdr_field(): [45]; uri=[sip:2345@sip.osp.com]
4(45262) DEBUG: [core/parser/msg_parser.c:174]: get_hdr_field(): to body (22)[sip:2345@sip.osp.com], to tag (16)[501b95048bf50805]
4(45262) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [From] type 4
4(45262) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [CSeq] type 5
4(45262) DEBUG: [core/parser/msg_parser.c:152]: get_hdr_field(): cseq : <1>
4(45262) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Call-ID] type 6
4(45262) DEBUG: [core/receive.c:392]: receive_msg(): --- received sip message - reply - call-id: [68443192-0f66b617ce5917df] - cseq: [1 CANCEL]
4(45262) DEBUG: [core/receive.c:263]: ksr_evrt_pre_routing(): event route core:pre-routing not defined
6(45264) DEBUG: [core/udp_server.c:715]: udp_rcv_loop(): received on udp socket: (106/100/345) [[SIP/2.0 487 Request Terminated 0D 0A Via: SIP/2.0/UDP 10.192.117.6:5084;branch=z9hG4bKafaa.fe4571d3000000]]
6(45264) DEBUG: [core/parser/parse_fline.c:247]: parse_first_line(): first line type 2 (reply(status)) flags 1
6(45264) DEBUG: [core/parser/msg_parser.c:732]: parse_msg(): SIP Reply (status):
6(45264) DEBUG: [core/parser/msg_parser.c:733]: parse_msg(): version: <SIP/2.0>
4(45262) DEBUG: app_lua [app_lua_api.c:511]: sr_lua_reload_script(): No need to reload [/opt/kamailio/kamailio.lua] is version 6(45264) DEBUG: [core/parser/msg_parser.c:735]: parse_msg(): status: <487>
3(45261) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: xinfo is str: 2024-10-31 10-54-06 [debug] /opt/kamailio/kamailio.lua:56: ksr_request_route: 21.28 ms

0
4(45262) DEBUG: app_lua [app_lua_api.c:688]: app_lua_run_ex(): executing Lua function: [[ksr_reply_route]]
6(45264) DEBUG: [core/parser/msg_parser.c:737]: parse_msg(): reason:
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Via] type 1
3(45261) INFO: <script>: 2024-10-31 10-54-06 [debug] /opt/kamailio/kamailio.lua:56: ksr_request_route: 21.28 ms 6(45264) DEBUG: [core/parser/parse_via.c:1309]: parse_via_param(): Found param type 232, = <z9hG4bKafaa.fe4571d 4(45262) DEBUG: app_lua [app_lua_api.c:690]: app_lua_run_ex(): lua top index is: 17

3(45261) DEBUG: app_lua [app_lua_mod.c:169]: sr_kemi_config_engine_lua(): execution of route type 1 with no name returned 1
3(45261) DEBUG: [core/receive.c:531]: receive_msg(): request-route executed in: 24264 usec
3000000000000000000000000.0>; state=16
6(45264) DEBUG: [core/parser/parse_via.c:2663]: parse_via(): end of header reached, state=5
6(45264) DEBUG: [core/parser/msg_parser.c:592]: parse_headers(): Via found, flags=2
6(45264) DEBUG: [core/parser/msg_parser.c:594]: parse_headers(): this is the first via
3(45261) DEBUG: tm [h_table.c:133]: free_cell_helper(): freeing transaction 0x735e6229d610 from t_lookup.c:2059
3(45261) WARNING: tm [h_table.c:141]: free_cell_helper(): removed cell 0x735e6229d610 is still linked in hash table (t_lookup.c:2059)
3(45261) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [To] type 3
6(45264) DEBUG: [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=501b95048bf50805
6(45264) DEBUG: [core/parser/parse_addr_spec.c:904]: parse_addr_spec(): end of header reached, state=29
6(45264) DEBUG: [core/parser/msg_parser.c:172]: get_hdr_field(): [45]; uri=[sip:2345@sip.osp.com]
6(45264) DEBUG: [core/parser/msg_parser.c:174]: get_hdr_field(): to body (22)[sip:2345@sip.osp.com], to tag (16)[501b95048bf50805]
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [From] type 4
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [CSeq] type 5
6(45264) DEBUG: [core/parser/msg_parser.c:152]: get_hdr_field(): cseq : <1>
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Call-ID] type 6
6(45264) DEBUG: [core/receive.c:392]: receive_msg(): --- received sip message - reply - call-id: [68443192-0f66b617ce5917df] - cseq: [1 INVITE]
6(45264) DEBUG: [core/receive.c:263]: ksr_evrt_pre_routing(): event route core:pre-routing not defined
6(45264) DEBUG: app_lua [app_lua_api.c:511]: sr_lua_reload_script(): No need to reload [/opt/kamailio/kamailio.lua] is version 0
6(45264) DEBUG: app_lua [app_lua_api.c:688]: app_lua_run_ex(): executing Lua function: [[ksr_reply_route]]
6(45264) DEBUG: app_lua [app_lua_api.c:690]: app_lua_run_ex(): lua top index is: 17
6(45264) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: xinfo is str: 2024-10-31 10-54-06 [debug] /opt/kamailio/kamailio.lua:67: ++ Reply received $rs $rr

6(45264) DEBUG: [core/pvapi.c:502]: pv_spec_lookup(): PV <$rs> is not in cache
6(45264) DEBUG: [core/pvapi.c:352]: pv_cache_add(): PV cache not initialized, doing it now
6(45264) DEBUG: [core/pvapi.c:386]: pv_cache_add(): pvar [$rs] added in cache
6(45264) DEBUG: [core/pvapi.c:502]: pv_spec_lookup(): PV <$rr> is not in cache
6(45264) DEBUG: [core/pvapi.c:386]: pv_cache_add(): pvar [$rr] added in cache
6(45264) INFO: <script>: 2024-10-31 10-54-06 [debug] /opt/kamailio/kamailio.lua:67: ++ Reply received 487 Request Terminated
6(45264) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $ci
4(45262) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: xinfo is str: 2024-10-31 10-54-06 [debug] /opt/kamailio/kamailio.lua:67: ++ Reply received $rs $rr

4(45262) DEBUG: [core/pvapi.c:502]: pv_spec_lookup(): PV <$rs> is not in cache
4(45262) DEBUG: [core/pvapi.c:352]: pv_cache_add(): PV cache not initialized, doing it now
4(45262) DEBUG: [core/pvapi.c:386]: pv_cache_add(): pvar [$rs] added in cache
4(45262) DEBUG: [core/pvapi.c:502]: pv_spec_lookup(): PV <$rr> is not in cache
4(45262) DEBUG: [core/pvapi.c:386]: pv_cache_add(): pvar [$rr] added in cache
4(45262) INFO: <script>: 2024-10-31 10-54-06 [debug] /opt/kamailio/kamailio.lua:67: ++ Reply received 200 OK
4(45262) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $ci
4(45262) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $ci
3(45261) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
3(45261) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
3(45261) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
3(45261) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
3(45261) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
3(45261) DEBUG: [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil)
3(45261) DEBUG: [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil)
3(45261) DEBUG: [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil)
3(45261) DEBUG: [core/receive.c:635]: receive_msg(): cleaning up
4(45262) DEBUG: [core/pvapi.c:386]: pv_cache_add(): pvar [$ci] added in cache
6(45264) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $ci
6(45264) DEBUG: [core/pvapi.c:386]: pv_cache_add(): pvar [$ci] added in cache
4(45262) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $mb
4(45262) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $mb
6(45264) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $mb
4(45262) DEBUG: [core/pvapi.c:386]: pv_cache_add(): pvar [$mb] added in cache
4(45262) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $mb
4(45262) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $mb
4(45262) DEBUG: [core/pvapi.c:410]: pv_cache_lookup(): pvar [$mb] found in cache
4(45262) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $ci
4(45262) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $ci
4(45262) DEBUG: [core/pvapi.c:410]: pv_cache_lookup(): pvar [$ci] found in cache
6(45264) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $mb
6(45264) DEBUG: [core/pvapi.c:386]: pv_cache_add(): pvar [$mb] added in cache
6(45264) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $mb
6(45264) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $mb
6(45264) DEBUG: [core/pvapi.c:410]: pv_cache_lookup(): pvar [$mb] found in cache
6(45264) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $ci
6(45264) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $ci
6(45264) DEBUG: [core/pvapi.c:410]: pv_cache_lookup(): pvar [$ci] found in cache
4(45262) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: xinfo is str: 2024-10-31 10-54-06 [debug] /opt/kamailio/routing.lua:181: $rs $rm Type: term State: callout Callid: 68443192-0f66b617ce5917df

4(45262) DEBUG: [core/pvapi.c:410]: pv_cache_lookup(): pvar [$rs] found in cache
4(45262) DEBUG: [core/pvapi.c:502]: pv_spec_lookup(): PV <$rm> is not in cache
4(45262) DEBUG: [core/pvapi.c:386]: pv_cache_add(): pvar [$rm] added in cache
4(45262) INFO: <script>: 2024-10-31 10-54-06 [debug] /opt/kamailio/routing.lua:181: 200 CANCEL Type: term State: callout Callid: 68443192-0f66b617ce5917df
4(45262) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $rs
4(45262) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $rs
4(45262) DEBUG: [core/pvapi.c:410]: pv_cache_lookup(): pvar [$rs] found in cache
4(45262) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $rs
4(45262) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $rs
4(45262) DEBUG: [core/pvapi.c:410]: pv_cache_lookup(): pvar [$rs] found in cache
4(45262) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $rs
4(45262) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $rs
4(45262) DEBUG: [core/pvapi.c:410]: pv_cache_lookup(): pvar [$rs] found in cache
4(45262) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $rs
4(45262) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $rs
4(45262) DEBUG: [core/pvapi.c:410]: pv_cache_lookup(): pvar [$rs] found in cache
4(45262) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $rs
4(45262) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $rs
4(45262) DEBUG: [core/pvapi.c:410]: pv_cache_lookup(): pvar [$rs] found in cache
4(45262) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $rs
4(45262) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $rs
4(45262) DEBUG: [core/pvapi.c:410]: pv_cache_lookup(): pvar [$rs] found in cache
4(45262) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $rm
4(45262) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $rm
4(45262) DEBUG: [core/pvapi.c:410]: pv_cache_lookup(): pvar [$rm] found in cache
4(45262) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $rs
4(45262) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $rs
4(45262) DEBUG: [core/pvapi.c:410]: pv_cache_lookup(): pvar [$rs] found in cache
4(45262) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $rm
4(45262) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $rm
4(45262) DEBUG: [core/pvapi.c:410]: pv_cache_lookup(): pvar [$rm] found in cache
4(45262) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: xinfo is str: 2024-10-31 10-54-06 [debug] /opt/kamailio/kamailio.lua:71: ksr_reply_route: 13.63 ms

4(45262) INFO: <script>: 2024-10-31 10-54-06 [debug] /opt/kamailio/kamailio.lua:71: ksr_reply_route: 13.63 ms EBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: xinfo is str: 2024-10-31 10-54-07 0m
4(45262) DEBUG: app_lua [app_lua_mod.c:169]: sr_kemi_config_engine_lua(): execution of route type 128 with no name returned 1
[debug] /opt/kamailio/routing.lua:181: $rs $rm Type: term State: callout Callid: 68443192-0f66b617ce5917df

6(45264) DEBUG: [core/pvapi.c:410]: pv_cache_lookup(): pvar [$rs] found in cache
6(45264) DEBUG: [core/pvapi.c:502]: pv_spec_lookup(): PV <$rm> is not in cache
6(45264) DEBUG: [core/pvapi.c:386]: pv_cache_add(): pvar [$rm] added in cache
4(45262) DEBUG: tm [t_lookup.c:1565]: t_check_msg(): msg (0x735e6b5b91d0) id=1/45262 global id=0/0 T start=0xffffffffffffffff
4(45262) DEBUG: tm [t_lookup.c:1410]: t_reply_matching(): t_reply_matching: hash 43770 label 0 branch 0
4(45262) DEBUG: tm [t_lookup.c:1539]: t_reply_matching(): no matching transaction exists
4(45262) DEBUG: tm [t_lookup.c:1542]: t_reply_matching(): failure to match a transaction
4(45262) DEBUG: tm [t_lookup.c:1637]: t_check_msg(): msg (0x735e6b5b91d0) id=1/45262 global id=1/45262 T end=(nil)
4(45262) DEBUG: tm [t_reply.c:2376]: reply_received(): transaction not found - (branch -1)
4(45262) DEBUG: app_lua [app_lua_api.c:511]: sr_lua_reload_script(): No need to reload [/opt/kamailio/kamailio.lua] is version 0
4(45262) DEBUG: app_lua [app_lua_api.c:688]: app_lua_run_ex(): executing Lua function: [[ksr_slreply]]
4(45262) DEBUG: app_lua [app_lua_api.c:690]: app_lua_run_ex(): lua top index is: 17
4(45262) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: xinfo is str: 2024-10-31 10-54-07 [debug] /opt/kamailio/kamailio.lua:169: Reply received on_sl_reply

4(45262) INFO: <script>: 2024-10-31 10-54-07 [debug] /opt/kamailio/kamailio.lua:169: Reply received on_sl_reply
4(45262) DEBUG: app_lua [app_lua_mod.c:166]: sr_kemi_config_engine_lua(): execution of route type 513 with name [ksr_slreply] returned 1
4(45262) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Server] type 29
4(45262) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Content-Length] type 12
4(45262) DEBUG: [core/parser/msg_parser.c:187]: get_hdr_field(): content_length=0
4(45262) DEBUG: [core/parser/msg_parser.c:91]: get_hdr_field(): found end of header
4(45262) DEBUG: [core/forward.c:901]: do_forward_reply(): reply cannot be forwarded - no 2nd via
4(45262) DEBUG: [core/receive.c:624]: receive_msg(): reply-route executed in: 22900 usec
4(45262) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
4(45262) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
4(45262) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
4(45262) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
4(45262) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
4(45262) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
4(45262) DEBUG: [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil)
4(45262) DEBUG: [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil)
4(45262) DEBUG: [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil)
4(45262) DEBUG: [core/receive.c:635]: receive_msg(): cleaning up
6(45264) INFO: <script>: 2024-10-31 10-54-07 [debug] /opt/kamailio/routing.lua:181: 487 INVITE Type: term State: callout Callid: 68443192-0f66b617ce5917df
6(45264) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $rs
6(45264) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $rs
6(45264) DEBUG: [core/pvapi.c:410]: pv_cache_lookup(): pvar [$rs] found in cache
6(45264) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $hdr(RAck)
6(45264) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $hdr(RAck)
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [RAck] type 0
6(45264) DEBUG: [core/pvapi.c:386]: pv_cache_add(): pvar [$hdr(RAck)] added in cache
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Server] type 29
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Content-Length] type 12
6(45264) DEBUG: [core/parser/msg_parser.c:187]: get_hdr_field(): content_length=0
6(45264) DEBUG: [core/parser/msg_parser.c:91]: get_hdr_field(): found end of header
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Via] type 1
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [RAck] type 0
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [To] type 3
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [RAck] type 0
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [From] type 4
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [RAck] type 0
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [CSeq] type 5
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [RAck] type 0
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Call-ID] type 6
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [RAck] type 0
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Server] type 29
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [RAck] type 0
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Content-Length] type 12
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [RAck] type 0
6(45264) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $hdr(Require)
6(45264) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $hdr(Require)
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Require] type 18
6(45264) DEBUG: pv [pv_core.c:3926]: pv_parse_hdr_name(): using hdr type (18) instead of
6(45264) DEBUG: [core/pvapi.c:386]: pv_cache_add(): pvar [$hdr(Require)] added in cache
6(45264) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $hdr(RSeq)
6(45264) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $hdr(RSeq)
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [RSeq] type 0
6(45264) DEBUG: [core/pvapi.c:386]: pv_cache_add(): pvar [$hdr(RSeq)] added in cache
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Via] type 1
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [RSeq] type 0
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [To] type 3
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [RSeq] type 0
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [From] type 4
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [RSeq] type 0
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [CSeq] type 5
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [RSeq] type 0
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Call-ID] type 6
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [RSeq] type 0
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Server] type 29
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [RSeq] type 0
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Content-Length] type 12
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [RSeq] type 0
6(45264) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $hdr(User-Agent)
6(45264) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $hdr(User-Agent)
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [User-Agent] type 28
6(45264) DEBUG: pv [pv_core.c:3926]: pv_parse_hdr_name(): using hdr type (28) instead of
6(45264) DEBUG: [core/pvapi.c:386]: pv_cache_add(): pvar [$hdr(User-Agent)] added in cache
6(45264) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $hdr(Accept)
6(45264) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $hdr(Accept)
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Accept] type 23
6(45264) DEBUG: pv [pv_core.c:3926]: pv_parse_hdr_name(): using hdr type (23) instead of
6(45264) DEBUG: [core/pvapi.c:386]: pv_cache_add(): pvar [$hdr(Accept)] added in cache
6(45264) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $hdr(Server)
6(45264) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $hdr(Server)
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Server] type 29
6(45264) DEBUG: pv [pv_core.c:3926]: pv_parse_hdr_name(): using hdr type (29) instead of
6(45264) DEBUG: [core/pvapi.c:386]: pv_cache_add(): pvar [$hdr(Server)] added in cache
6(45264) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $hdr(Server)
6(45264) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $hdr(Server)
6(45264) DEBUG: [core/pvapi.c:410]: pv_cache_lookup(): pvar [$hdr(Server)] found in cache
6(45264) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $hdr(Supported)
6(45264) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $hdr(Supported)
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Supported] type 17
6(45264) DEBUG: pv [pv_core.c:3926]: pv_parse_hdr_name(): using hdr type (17) instead of
6(45264) DEBUG: [core/pvapi.c:386]: pv_cache_add(): pvar [$hdr(Supported)] added in cache
6(45264) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $hdr(Allow)
6(45264) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $hdr(Allow)
6(45264) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Allow] type 21
6(45264) DEBUG: pv [pv_core.c:3926]: pv_parse_hdr_name(): using hdr type (21) instead of
6(45264) DEBUG: [core/pvapi.c:386]: pv_cache_add(): pvar [$hdr(Allow)] added in cache
6(45264) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $rm
6(45264) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $rm
6(45264) DEBUG: [core/pvapi.c:410]: pv_cache_lookup(): pvar [$rm] found in cache
6(45264) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $rs
6(45264) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $rs
6(45264) DEBUG: [core/pvapi.c:410]: pv_cache_lookup(): pvar [$rs] found in cache
6(45264) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: xinfo is str: 2024-10-31 10-54-07 [debug] /opt/kamailio/kamailio.lua:71: ksr_reply_route: 26.79 ms

6(45264) INFO: <script>: 2024-10-31 10-54-07 [debug] /opt/kamailio/kamailio.lua:71: ksr_reply_route: 26.79 ms
6(45264) DEBUG: app_lua [app_lua_mod.c:169]: sr_kemi_config_engine_lua(): execution of route type 128 with no name returned 1
6(45264) DEBUG: tm [t_lookup.c:1565]: t_check_msg(): msg (0x735e6b5b91d0) id=1/45264 global id=0/0 T start=0xffffffffffffffff
6(45264) DEBUG: tm [t_lookup.c:1410]: t_reply_matching(): t_reply_matching: hash 43770 label 0 branch 0
6(45264) DEBUG: tm [t_lookup.c:1539]: t_reply_matching(): no matching transaction exists
6(45264) DEBUG: tm [t_lookup.c:1542]: t_reply_matching(): failure to match a transaction
6(45264) DEBUG: tm [t_lookup.c:1637]: t_check_msg(): msg (0x735e6b5b91d0) id=1/45264 global id=1/45264 T end=(nil)
6(45264) DEBUG: tm [t_reply.c:2376]: reply_received(): transaction not found - (branch -1)
6(45264) DEBUG: app_lua [app_lua_api.c:511]: sr_lua_reload_script(): No need to reload [/opt/kamailio/kamailio.lua] is version 0
6(45264) DEBUG: app_lua [app_lua_api.c:688]: app_lua_run_ex(): executing Lua function: [[ksr_slreply]]
6(45264) DEBUG: app_lua [app_lua_api.c:690]: app_lua_run_ex(): lua top index is: 17
6(45264) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: xinfo is str: 2024-10-31 10-54-07 [debug] /opt/kamailio/kamailio.lua:169: Reply received on_sl_reply

6(45264) INFO: <script>: 2024-10-31 10-54-07 [debug] /opt/kamailio/kamailio.lua:169: Reply received on_sl_reply
6(45264) DEBUG: app_lua [app_lua_mod.c:166]: sr_kemi_config_engine_lua(): execution of route type 513 with name [ksr_slreply] returned 1
6(45264) DEBUG: [core/forward.c:901]: do_forward_reply(): reply cannot be forwarded - no 2nd via
6(45264) DEBUG: [core/receive.c:624]: receive_msg(): reply-route executed in: 28304 usec
6(45264) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
6(45264) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
6(45264) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
6(45264) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
6(45264) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
6(45264) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
6(45264) DEBUG: [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil)
6(45264) DEBUG: [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil)
6(45264) DEBUG: [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil)
6(45264) DEBUG: [core/receive.c:635]: receive_msg(): cleaning up
5(45263) DEBUG: [core/udp_server.c:715]: udp_rcv_loop(): received on udp socket: (106/100/345) [[SIP/2.0 487 Request Terminated 0D 0A Via: SIP/2.0/UDP 10.192.117.6:5084;branch=z9hG4bKafaa.fe4571d3000000]]
5(45263) DEBUG: [core/parser/parse_fline.c:247]: parse_first_line(): first line type 2 (reply(status)) flags 1
5(45263) DEBUG: [core/parser/msg_parser.c:732]: parse_msg(): SIP Reply (status):
5(45263) DEBUG: [core/parser/msg_parser.c:733]: parse_msg(): version: <SIP/2.0>
5(45263) DEBUG: [core/parser/msg_parser.c:735]: parse_msg(): status: <487>
5(45263) DEBUG: [core/parser/msg_parser.c:737]: parse_msg(): reason:
5(45263) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Via] type 1
5(45263) DEBUG: [core/parser/parse_via.c:1309]: parse_via_param(): Found param type 232, = <z9hG4bKafaa.fe4571d3000000000000000000000000.0>; state=16
5(45263) DEBUG: [core/parser/parse_via.c:2663]: parse_via(): end of header reached, state=5
5(45263) DEBUG: [core/parser/msg_parser.c:592]: parse_headers(): Via found, flags=2
5(45263) DEBUG: [core/parser/msg_parser.c:594]: parse_headers(): this is the first via
5(45263) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [To] type 3
5(45263) DEBUG: [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=501b95048bf50805
5(45263) DEBUG: [core/parser/parse_addr_spec.c:904]: parse_addr_spec(): end of header reached, state=29
5(45263) DEBUG: [core/parser/msg_parser.c:172]: get_hdr_field(): [45]; uri=[sip:2345@sip.osp.com]
5(45263) DEBUG: [core/parser/msg_parser.c:174]: get_hdr_field(): to body (22)[sip:2345@sip.osp.com], to tag (16)[501b95048bf50805]
5(45263) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [From] type 4
5(45263) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [CSeq] type 5
5(45263) DEBUG: [core/parser/msg_parser.c:152]: get_hdr_field(): cseq : <1>
5(45263) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Call-ID] type 6
5(45263) DEBUG: [core/receive.c:392]: receive_msg(): --- received sip message - reply - call-id: [68443192-0f66b617ce5917df] - cseq: [1 INVITE]
5(45263) DEBUG: [core/receive.c:263]: ksr_evrt_pre_routing(): event route core:pre-routing not defined
5(45263) DEBUG: app_lua [app_lua_api.c:511]: sr_lua_reload_script(): No need to reload [/opt/kamailio/kamailio.lua] is version 0
5(45263) DEBUG: app_lua [app_lua_api.c:688]: app_lua_run_ex(): executing Lua function: [[ksr_reply_route]]
5(45263) DEBUG: app_lua [app_lua_api.c:690]: app_lua_run_ex(): lua top index is: 17
5(45263) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: xinfo is str: 2024-10-31 10-54-07 [debug] /opt/kamailio/kamailio.lua:67: ++ Reply received $rs $rr

5(45263) DEBUG: [core/pvapi.c:502]: pv_spec_lookup(): PV <$rs> is not in cache
5(45263) DEBUG: [core/pvapi.c:352]: pv_cache_add(): PV cache not initialized, doing it now
5(45263) DEBUG: [core/pvapi.c:386]: pv_cache_add(): pvar [$rs] added in cache
5(45263) DEBUG: [core/pvapi.c:502]: pv_spec_lookup(): PV <$rr> is not in cache
5(45263) DEBUG: [core/pvapi.c:386]: pv_cache_add(): pvar [$rr] added in cache
5(45263) INFO: <script>: 2024-10-31 10-54-07 [debug] /opt/kamailio/kamailio.lua:67: ++ Reply received 487 Request Terminated
5(45263) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $ci
5(45263) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $ci
5(45263) DEBUG: [core/pvapi.c:386]: pv_cache_add(): pvar [$ci] added in cache
5(45263) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $mb
5(45263) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $mb
5(45263) DEBUG: [core/pvapi.c:386]: pv_cache_add(): pvar [$mb] added in cache
5(45263) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $mb
5(45263) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $mb
5(45263) DEBUG: [core/pvapi.c:410]: pv_cache_lookup(): pvar [$mb] found in cache
5(45263) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: xinfo is str: 2024-10-31 10-54-07 [debug] /opt/kamailio/kamailio.lua:71: ksr_reply_route: 6.68 ms

5(45263) INFO: <script>: 2024-10-31 10-54-07 [debug] /opt/kamailio/kamailio.lua:71: ksr_reply_route: 6.68 ms
5(45263) DEBUG: app_lua [app_lua_mod.c:169]: sr_kemi_config_engine_lua(): execution of route type 128 with no name returned 1
5(45263) DEBUG: tm [t_lookup.c:1565]: t_check_msg(): msg (0x735e6b5b91d0) id=1/45263 global id=0/0 T start=0xffffffffffffffff
5(45263) DEBUG: tm [t_lookup.c:1410]: t_reply_matching(): t_reply_matching: hash 43770 label 0 branch 0
5(45263) DEBUG: tm [t_lookup.c:1539]: t_reply_matching(): no matching transaction exists
5(45263) DEBUG: tm [t_lookup.c:1542]: t_reply_matching(): failure to match a transaction
5(45263) DEBUG: tm [t_lookup.c:1637]: t_check_msg(): msg (0x735e6b5b91d0) id=1/45263 global id=1/45263 T end=(nil)
5(45263) DEBUG: tm [t_reply.c:2376]: reply_received(): transaction not found - (branch -1)
5(45263) DEBUG: app_lua [app_lua_api.c:511]: sr_lua_reload_script(): No need to reload [/opt/kamailio/kamailio.lua] is version 0
5(45263) DEBUG: app_lua [app_lua_api.c:688]: app_lua_run_ex(): executing Lua function: [[ksr_slreply]]
5(45263) DEBUG: app_lua [app_lua_api.c:690]: app_lua_run_ex(): lua top index is: 17
5(45263) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: xinfo is str: 2024-10-31 10-54-07 [debug] /opt/kamailio/kamailio.lua:169: Reply received on_sl_reply

5(45263) INFO: <script>: 2024-10-31 10-54-07 [debug] /opt/kamailio/kamailio.lua:169: Reply received on_sl_reply
5(45263) DEBUG: app_lua [app_lua_mod.c:166]: sr_kemi_config_engine_lua(): execution of route type 513 with name [ksr_slreply] returned 1
5(45263) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Server] type 29
5(45263) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Content-Length] type 12
5(45263) DEBUG: [core/parser/msg_parser.c:187]: get_hdr_field(): content_length=0
5(45263) DEBUG: [core/parser/msg_parser.c:91]: get_hdr_field(): found end of header
5(45263) DEBUG: [core/forward.c:901]: do_forward_reply(): reply cannot be forwarded - no 2nd via
5(45263) DEBUG: [core/receive.c:624]: receive_msg(): reply-route executed in: 8967 usec
5(45263) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
5(45263) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
5(45263) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
5(45263) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
5(45263) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
5(45263) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
5(45263) DEBUG: [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil)
5(45263) DEBUG: [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil)
5(45263) DEBUG: [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil)
5(45263) DEBUG: [core/receive.c:635]: receive_msg(): cleaning up
7(45265) DEBUG: [core/udp_server.c:715]: udp_rcv_loop(): received on udp socket: (106/100/345) [[SIP/2.0 487 Request Terminated 0D 0A Via: SIP/2.0/UDP 10.192.117.6:5084;branch=z9hG4bKafaa.fe4571d3000000]]
7(45265) DEBUG: [core/parser/parse_fline.c:247]: parse_first_line(): first line type 2 (reply(status)) flags 1
7(45265) DEBUG: [core/parser/msg_parser.c:732]: parse_msg(): SIP Reply (status):
7(45265) DEBUG: [core/parser/msg_parser.c:733]: parse_msg(): version: <SIP/2.0>
7(45265) DEBUG: [core/parser/msg_parser.c:735]: parse_msg(): status: <487>
7(45265) DEBUG: [core/parser/msg_parser.c:737]: parse_msg(): reason:
7(45265) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Via] type 1
7(45265) DEBUG: [core/parser/parse_via.c:1309]: parse_via_param(): Found param type 232, = <z9hG4bKafaa.fe4571d3000000000000000000000000.0>; state=16
7(45265) DEBUG: [core/parser/parse_via.c:2663]: parse_via(): end of header reached, state=5
7(45265) DEBUG: [core/parser/msg_parser.c:592]: parse_headers(): Via found, flags=2
7(45265) DEBUG: [core/parser/msg_parser.c:594]: parse_headers(): this is the first via
7(45265) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [To] type 3
7(45265) DEBUG: [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=501b95048bf50805
7(45265) DEBUG: [core/parser/parse_addr_spec.c:904]: parse_addr_spec(): end of header reached, state=29
7(45265) DEBUG: [core/parser/msg_parser.c:172]: get_hdr_field(): [45]; uri=[sip:2345@sip.osp.com]
7(45265) DEBUG: [core/parser/msg_parser.c:174]: get_hdr_field(): to body (22)[sip:2345@sip.osp.com], to tag (16)[501b95048bf50805]
7(45265) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [From] type 4
7(45265) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [CSeq] type 5
7(45265) DEBUG: [core/parser/msg_parser.c:152]: get_hdr_field(): cseq : <1>
7(45265) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Call-ID] type 6
7(45265) DEBUG: [core/receive.c:392]: receive_msg(): --- received sip message - reply - call-id: [68443192-0f66b617ce5917df] - cseq: [1 INVITE]
7(45265) DEBUG: [core/receive.c:263]: ksr_evrt_pre_routing(): event route core:pre-routing not defined
7(45265) DEBUG: app_lua [app_lua_api.c:511]: sr_lua_reload_script(): No need to reload [/opt/kamailio/kamailio.lua] is version 0
7(45265) DEBUG: app_lua [app_lua_api.c:688]: app_lua_run_ex(): executing Lua function: [[ksr_reply_route]]
7(45265) DEBUG: app_lua [app_lua_api.c:690]: app_lua_run_ex(): lua top index is: 17
7(45265) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: xinfo is str: 2024-10-31 10-54-08 [debug] /opt/kamailio/kamailio.lua:67: ++ Reply received $rs $rr

7(45265) DEBUG: [core/pvapi.c:502]: pv_spec_lookup(): PV <$rs> is not in cache
7(45265) DEBUG: [core/pvapi.c:352]: pv_cache_add(): PV cache not initialized, doing it now
7(45265) DEBUG: [core/pvapi.c:386]: pv_cache_add(): pvar [$rs] added in cache
7(45265) DEBUG: [core/pvapi.c:502]: pv_spec_lookup(): PV <$rr> is not in cache
7(45265) DEBUG: [core/pvapi.c:386]: pv_cache_add(): pvar [$rr] added in cache
7(45265) INFO: <script>: 2024-10-31 10-54-08 [debug] /opt/kamailio/kamailio.lua:67: ++ Reply received 487 Request Terminated
7(45265) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $ci
7(45265) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $ci
7(45265) DEBUG: [core/pvapi.c:386]: pv_cache_add(): pvar [$ci] added in cache
7(45265) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $mb
7(45265) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $mb
7(45265) DEBUG: [core/pvapi.c:386]: pv_cache_add(): pvar [$mb] added in cache
7(45265) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: get is str: $mb
7(45265) DEBUG: [core/kemi.c:2988]: sr_kemi_pv_get_mode(): pv get: $mb
7(45265) DEBUG: [core/pvapi.c:410]: pv_cache_lookup(): pvar [$mb] found in cache
7(45265) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: xinfo is str: 2024-10-31 10-54-08 [debug] /opt/kamailio/kamailio.lua:71: ksr_reply_route: 6.48 ms

7(45265) INFO: <script>: 2024-10-31 10-54-08 [debug] /opt/kamailio/kamailio.lua:71: ksr_reply_route: 6.48 ms
7(45265) DEBUG: app_lua [app_lua_mod.c:169]: sr_kemi_config_engine_lua(): execution of route type 128 with no name returned 1
7(45265) DEBUG: tm [t_lookup.c:1565]: t_check_msg(): msg (0x735e6b5b91d0) id=1/45265 global id=0/0 T start=0xffffffffffffffff
7(45265) DEBUG: tm [t_lookup.c:1410]: t_reply_matching(): t_reply_matching: hash 43770 label 0 branch 0
7(45265) DEBUG: tm [t_lookup.c:1539]: t_reply_matching(): no matching transaction exists
7(45265) DEBUG: tm [t_lookup.c:1542]: t_reply_matching(): failure to match a transaction
7(45265) DEBUG: tm [t_lookup.c:1637]: t_check_msg(): msg (0x735e6b5b91d0) id=1/45265 global id=1/45265 T end=(nil)
7(45265) DEBUG: tm [t_reply.c:2376]: reply_received(): transaction not found - (branch -1)
7(45265) DEBUG: app_lua [app_lua_api.c:511]: sr_lua_reload_script(): No need to reload [/opt/kamailio/kamailio.lua] is version 0
7(45265) DEBUG: app_lua [app_lua_api.c:688]: app_lua_run_ex(): executing Lua function: [[ksr_slreply]]
7(45265) DEBUG: app_lua [app_lua_api.c:690]: app_lua_run_ex(): lua top index is: 17
7(45265) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: xinfo is str: 2024-10-31 10-54-08 [debug] /opt/kamailio/kamailio.lua:169: Reply received on_sl_reply

7(45265) INFO: <script>: 2024-10-31 10-54-08 [debug] /opt/kamailio/kamailio.lua:169: Reply received on_sl_reply
7(45265) DEBUG: app_lua [app_lua_mod.c:166]: sr_kemi_config_engine_lua(): execution of route type 513 with name [ksr_slreply] returned 1
7(45265) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Server] type 29
7(45265) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Content-Length] type 12
7(45265) DEBUG: [core/parser/msg_parser.c:187]: get_hdr_field(): content_length=0
7(45265) DEBUG: [core/parser/msg_parser.c:91]: get_hdr_field(): found end of header
7(45265) DEBUG: [core/forward.c:901]: do_forward_reply(): reply cannot be forwarded - no 2nd via
7(45265) DEBUG: [core/receive.c:624]: receive_msg(): reply-route executed in: 8419 usec
7(45265) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
7(45265) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
7(45265) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
7(45265) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
7(45265) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
7(45265) DEBUG: [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
7(45265) DEBUG: [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil)
7(45265) DEBUG: [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil)
7(45265) DEBUG: [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil)
7(45265) DEBUG: [core/receive.c:635]: receive_msg(): cleaning up
8(45266) DEBUG: [core/udp_server.c:715]: udp_rcv_loop(): received on udp socket: (106/100/345) [[SIP/2.0 487 Request Terminated 0D 0A Via: SIP/2.0/UDP 10.192.117.6:5084;branch=z9hG4bKafaa.fe4571d3000000]]
8(45266) DEBUG: [core/parser/parse_fline.c:247]: parse_first_line(): first line type 2 (reply(status)) flags 1
8(45266) DEBUG: [core/parser/msg_parser.c:732]: parse_msg(): SIP Reply (status):
8(45266) DEBUG: [core/parser/msg_parser.c:733]: parse_msg(): version: <SIP/2.0>
8(45266) DEBUG: [core/parser/msg_parser.c:735]: parse_msg(): status: <487>
8(45266) DEBUG: [core/parser/msg_parser.c:737]: parse_msg(): reason:
8(45266) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Via] type 1
8(45266) DEBUG: [core/parser/parse_via.c:1309]: parse_via_param(): Found param type 232, = <z9hG4bKafaa.fe4571d3000000000000000000000000.0>; state=16
8(45266) DEBUG: [core/parser/parse_via.c:2663]: parse_via(): end of header reached, state=5
8(45266) DEBUG: [core/parser/msg_parser.c:592]: parse_headers(): Via found, flags=2
8(45266) DEBUG: [core/parser/msg_parser.c:594]: parse_headers(): this is the first via
8(45266) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [To] type 3
8(45266) DEBUG: [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=501b95048bf50805
8(45266) DEBUG: [core/parser/parse_addr_spec.c:904]: parse_addr_spec(): end of header reached, state=29
8(45266) DEBUG: [core/parser/msg_parser.c:172]: get_hdr_field(): [45]; uri=[sip:2345@sip.osp.com]
8(45266) DEBUG: [core/parser/msg_parser.c:174]: get_hdr_field(): to body (22)[sip:2345@sip.osp.com], to tag (16)[501b95048bf50805]
8(45266) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [From] type 4
8(45266) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [CSeq] type 5
8(45266) DEBUG: [core/parser/msg_parser.c:152]: get_hdr_field(): cseq : <1>
8(45266) DEBUG: [core/parser/parse_hname2.c:315]: parse_sip_header_name(): parsed header name [Call-ID] type 6
8(45266) DEBUG: [core/receive.c:392]: receive_msg(): --- received sip message - reply - call-id: [68443192-0f66b617ce5917df] - cseq: [1 INVITE]
8(45266) DEBUG: [core/receive.c:263]: ksr_evrt_pre_routing(): event route core:pre-routing not defined
8(45266) DEBUG: app_lua [app_lua_api.c:511]: sr_lua_reload_script(): No need to reload [/opt/kamailio/kamailio.lua] is version 0
8(45266) DEBUG: app_lua [app_lua_api.c:688]: app_lua_run_ex(): executing Lua function: [[ksr_reply_route]]
8(45266) DEBUG: app_lua [app_lua_api.c:690]: app_lua_run_ex(): lua top index is: 17
8(45266) DEBUG: app_lua [app_lua_api.c:1023]: sr_kemi_lua_exec_func_ex(): param[0] for: xinfo is str: 2024-10-31 10-54-10 [debug] /opt/kamailio/kamailio.lua:67: ++ Reply received $rs $rr

—
Reply to this email directly, view it on GitHub, or unsubscribe.
You are receiving this because you are subscribed to this thread.Message ID: <kamailio/kamailio/issues/4011@github.com>