Sorry, if i could not explain it well before. I hope below picture will make it clear.

[image: image.png]

is it some configuration issue?

BTW what is the best way to call multiple async functions in kamailio.

Any suggestion is much appreciated.

Best Regards,

Aqs Younas

On Wed, 11 Jul 2018 at 12:39, Daniel-Constantin Mierla miconda@gmail.com wrote:

Hello,

On 10.07.18 22:08, Aqs Younas wrote:

Greeting list,

I am using two async functions(http_async_query) in configuration one for authentication and other one for push notifications. I am also using tsilio module to suspend the transaction and resumed it.

I am resetting this flag 'T_ASYNC_SUSPENDED' before suspending the transaction. Everything is working fine except. When caller send CANCEL on the call, kamailio successfully completes sip flow at callee(B party) side but send back below packet towards caller.

what the above statement means? Kamailio forwarded the invite to callee, got 200ok, but sends back the 200 response?

Cheers, Daniel

2018/07/10 19:47:41.125893 172.31.21.87:5060 -> 39.38.156.111:59969 SIP/2.0 500 I'm terribly sorry, server error occurred (1/TM ) Via: SIP/2.0/UDP 39.38.156.111:59969 ;branch=z9hG4bK-524287-1---91c6114330fe6293;rport=59969 To: sip:923335550609@sip.talkhomeappcall.com ;transport=UDP;tag=9fe2d4c84d97a4af81aa65ca8fc51b3d-62cb From: sip:923135082344@sip.talkhomeappcall.com ;transport=UDP;tag=d72eaf4c Call-ID: VkAwxpSgkKSGn5dXaXgn5A.. CSeq: 2 INVITE Content-Length: 0

root@sip:~# kamailio -V version: kamailio 5.1.3 (x86_64/linux) flags: STATS: Off, USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, 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_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. id: unknown compiled on 08:06:26 May 2 2018 with gcc 4.9.2

Could someone please help me out how to fix this. Cancels are handles automatically so, i cannot hardcore anything to resolve it.

Best Regards,

Aqs Younas

---

Kamailio (SER) - Users Mailing Listsr-users@lists.kamailio.orghttps://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users

-- Daniel-Constantin Mierla -- www.asipto.comwww.twitter.com/miconda -- www.linkedin.com/in/miconda Kamailio World Conference -- www.kamailioworld.com

I could not find anything related to error. Below are the full detailed logs. Again thanks for you help.

Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): received on udp socket: (106/100/963) [[INVITE sip:923335550609@sip.talkhomeappcall.com;transport=UDP SIP/2.0 0D 0A Via: SIP/2.0/UDP 115.186.137.]] Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): SIP Request: Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg(): method: <INVITE> Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:608]: parse_msg(): uri: < sip:923335550609@sip.talkhomeappcall.com;transport=UDP> Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): version: <SIP/2.0> Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-524287-1---5e6fadd00170a89c>; state=16 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): Via found, flags=2 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): this is the first via Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [58]; uri=[ sip:923335550609@sip.talkhomeappcall.com;transport=UDP] Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [< sip:923335550609@sip.talkhomeappcall.com;transport=UDP>#015#012] Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <INVITE> Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/receive.c:205]: receive_msg(): --- received sip message - request - call-id: [v51-8AifZ2mXi4RFMRej9A..] - cseq: [1 INVITE] Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/receive.c:248]: receive_msg(): preparing to run routing scripts... Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=245 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=dc4e5a14 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: sanity [sanity_mod.c:256]: w_sanity_check(): sanity checks result: 1 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: maxfwd [mf_funcs.c:74]: is_maxfwd_present(): value = 70 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: maxfwd [maxfwd.c:148]: process_maxfwd_header(): value 70 decreased to 50 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: siputils [sipops.c:159]: is_first_hop(): no 2nd via found - first hop Jul 12 08:12:00 sip kamailio[22303]: DEBUG: textops [textops.c:3083]: has_body_helper(): content type is 196611 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/sdp/sdp_helpr_funcs.c:504]: extract_mediaip(): located IP address [115.186.137.147] in `o=' field Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/sdp/sdp_helpr_funcs.c:504]: extract_mediaip(): located IP address [115.186.137.147] in `c=' field Jul 12 08:12:00 sip kamailio[22303]: DEBUG: rtpengine [rtpengine_funcs.c:140]: check_content_type(): type <application/sdp> found valid Jul 12 08:12:00 sip kamailio[22303]: DEBUG: rtpengine [rtpengine.c:2704]: select_rtpp_node_old(): rtpengine hash table lookup failed to find node for calllen=24 callid=v51-8AifZ2mXi4RFMRej9A.. viabranch= Jul 12 08:12:00 sip kamailio[22303]: DEBUG: rtpengine [rtpengine.c:2251]: rtpp_function_call(): proxy reply: d3:sdp321:v=0#015#012o=Z 0 0 IN IP4 18.130.57.226#015#012s=Z#015#012c=IN IP4 18.130.57.226#015#012t=0 0#015#012m=audio 20324 RTP/AVP 3 110 8 0 97 101#015#012a=rtpmap:3 GSM/8000#015#012a=rtpmap:110 speex/8000#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:97 iLBC/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:97 mode=30#015#012a=fmtp:101 0-16#015#012a=sendrecv#015#012a=rtcp:20325#015#0126:result2:oke Jul 12 08:12:00 sip kamailio[22303]: DEBUG: rtpengine [rtpengine.c:2320]: rtpp_function_call(): rtpengine hash table insert node=udp:127.0.0.1:2223 for calllen=24 callid=v51-8AifZ2mXi4RFMRej9A.. viabranch= Jul 12 08:12:00 sip kamailio[22303]: DEBUG: siputils [checks.c:120]: has_totag(): no totag Jul 12 08:12:00 sip kamailio[22303]: DEBUG: rr [loose.c:1209]: is_direction(): param ftag not found Jul 12 08:12:00 sip kamailio[22303]: INFO: <script>: v51-8AifZ2mXi4RFMRej9A..|log|originated from User-Agent: Z 3.7.30891 r30851 Jul 12 08:12:00 sip kamailio[22303]: INFO: <script>: [R-ATTEMPT-AUTHORIZATION:v51-8AifZ2mXi4RFMRej9A..] -> In authentication for INVITE against 923135082344@sip.talkhomeappcall.com Jul 12 08:12:00 sip kamailio[22303]: INFO: <script>: [R-ATTEMPT-AUTHORIZATION:v51-8AifZ2mXi4RFMRej9A..] -> got password: e5ef068edf311111111000002124bf90 from cache against 923135082344@sip.talkhomeappcall.com Jul 12 08:12:00 sip kamailio[22303]: DEBUG: auth [auth_mod.c:847]: w_pv_auth_check(): realm [sip.talkhomeappcall.com] flags [1] checks [1] Jul 12 08:12:00 sip kamailio[22303]: DEBUG: auth [api.c:78]: pre_auth(): Credentials with realm 'sip.talkhomeappcall.com' not found Jul 12 08:12:00 sip kamailio[22303]: DEBUG: auth [auth_mod.c:508]: pv_authenticate(): no credentials Jul 12 08:12:00 sip kamailio[22303]: DEBUG: auth [challenge.c:165]: get_challenge_hf(): realm='sip.talkhomeappcall.com' Jul 12 08:12:00 sip kamailio[22303]: DEBUG: auth [challenge.c:275]: get_challenge_hf(): auth: 'Proxy-Authenticate: Digest realm=" sip.talkhomeappcall.com", nonce="W0cOfFtHDVBWPzjaU1WezcAAr+iIrJXl"#015#012' Jul 12 08:12:00 sip kamailio[22303]: DEBUG: sl [sl.c:282]: send_reply(): reply in stateless mode (sl) Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/msg_translator.c:159]: check_via_address(): (115.186.137.147, 115.186.137.147, 0) Jul 12 08:12:00 sip kamailio[22303]: WARNING: <script>: [R-CHECK-AUTHORIZATION:v51-8AifZ2mXi4RFMRej9A..] -> issued auth challenge to failed INVITE attempt for 923135082344@sip.talkhomeappcall.com from IP 115.186.137.147:61717 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/receive.c:289]: receive_msg(): request-route executed in: 3405 usec Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil) Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/sdp/sdp.c:794]: free_sdp(): _sdp = 0x7f3ac975eb18 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/sdp/sdp.c:796]: free_sdp(): sdp = 0x7f3ac975feb8 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/sdp/sdp.c:798]: free_sdp(): session = 0x7f3ac9729ce0 Jul 12 08:12:00 sip kamailio[22302]: DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): received on udp socket: (106/100/419) [[ACK sip:923335550609@sip.talkhomeappcall.com;transport=UDP SIP/2.0 0D 0A Via: SIP/2.0/UDP 115.186.137.147]] Jul 12 08:12:00 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): SIP Request: Jul 12 08:12:00 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg(): method: <ACK> Jul 12 08:12:00 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:608]: parse_msg(): uri: < sip:923335550609@sip.talkhomeappcall.com;transport=UDP> Jul 12 08:12:00 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): version: <SIP/2.0> Jul 12 08:12:00 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-524287-1---5e6fadd00170a89c>; state=16 Jul 12 08:12:00 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Jul 12 08:12:00 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): Via found, flags=2 Jul 12 08:12:00 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): this is the first via Jul 12 08:12:00 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=24981d2e17dbb5775661067d94809cd2.e7c9 Jul 12 08:12:00 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 Jul 12 08:12:00 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [100]; uri=[ sip:923335550609@sip.talkhomeappcall.com;transport=UDP] Jul 12 08:12:00 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [< sip:923335550609@sip.talkhomeappcall.com;transport=UDP>] Jul 12 08:12:00 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <ACK> Jul 12 08:12:00 sip kamailio[22302]: DEBUG: <core> [core/receive.c:205]: receive_msg(): --- received sip message - request - call-id: [v51-8AifZ2mXi4RFMRej9A..] - cseq: [1 ACK] Jul 12 08:12:00 sip kamailio[22302]: DEBUG: <core> [core/receive.c:248]: receive_msg(): preparing to run routing scripts... Jul 12 08:12:00 sip kamailio[22302]: DEBUG: sl [sl_funcs.c:406]: sl_filter_ACK(): SL local ACK found -> dropping it! Jul 12 08:12:00 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:00 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:00 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:00 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:00 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:00 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:00 sip kamailio[22302]: DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil) Jul 12 08:12:00 sip kamailio[22302]: DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): received on udp socket: (106/100/1208) [[INVITE sip:923335550609@sip.talkhomeappcall.com;transport=UDP SIP/2.0 0D 0A Via: SIP/2.0/UDP 115.186.137.]] Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): SIP Request: Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg(): method: <INVITE> Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:608]: parse_msg(): uri: < sip:923335550609@sip.talkhomeappcall.com;transport=UDP> Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): version: <SIP/2.0> Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-524287-1---6a391e4fb0f8a8f6>; state=16 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): Via found, flags=2 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): this is the first via Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [58]; uri=[ sip:923335550609@sip.talkhomeappcall.com;transport=UDP] Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [< sip:923335550609@sip.talkhomeappcall.com;transport=UDP>#015#012] Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <2> <INVITE> Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/receive.c:205]: receive_msg(): --- received sip message - request - call-id: [v51-8AifZ2mXi4RFMRej9A..] - cseq: [2 INVITE] Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/receive.c:248]: receive_msg(): preparing to run routing scripts... Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=245 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=dc4e5a14 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: sanity [sanity_mod.c:256]: w_sanity_check(): sanity checks result: 1 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: maxfwd [mf_funcs.c:74]: is_maxfwd_present(): value = 70 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: maxfwd [maxfwd.c:148]: process_maxfwd_header(): value 70 decreased to 50 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: siputils [sipops.c:159]: is_first_hop(): no 2nd via found - first hop Jul 12 08:12:00 sip kamailio[22303]: DEBUG: textops [textops.c:3083]: has_body_helper(): content type is 196611 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/sdp/sdp_helpr_funcs.c:504]: extract_mediaip(): located IP address [115.186.137.147] in `o=' field Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/sdp/sdp_helpr_funcs.c:504]: extract_mediaip(): located IP address [115.186.137.147] in `c=' field Jul 12 08:12:00 sip kamailio[22303]: DEBUG: rtpengine [rtpengine_funcs.c:140]: check_content_type(): type <application/sdp> found valid Jul 12 08:12:00 sip kamailio[22303]: DEBUG: rtpengine [rtpengine.c:2708]: select_rtpp_node_old(): rtpengine hash table lookup find node=udp: 127.0.0.1:2223 for calllen=24 callid=v51-8AifZ2mXi4RFMRej9A.. viabranch= Jul 12 08:12:00 sip kamailio[22303]: DEBUG: rtpengine [rtpengine.c:2251]: rtpp_function_call(): proxy reply: d3:sdp321:v=0#015#012o=Z 0 0 IN IP4 18.130.57.226#015#012s=Z#015#012c=IN IP4 18.130.57.226#015#012t=0 0#015#012m=audio 20324 RTP/AVP 3 110 8 0 97 101#015#012a=rtpmap:3 GSM/8000#015#012a=rtpmap:110 speex/8000#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:97 iLBC/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:97 mode=30#015#012a=fmtp:101 0-16#015#012a=sendrecv#015#012a=rtcp:20325#015#0126:result2:oke Jul 12 08:12:00 sip kamailio[22303]: DEBUG: siputils [checks.c:120]: has_totag(): no totag Jul 12 08:12:00 sip kamailio[22303]: DEBUG: rr [loose.c:1209]: is_direction(): param ftag not found Jul 12 08:12:00 sip kamailio[22303]: INFO: <script>: v51-8AifZ2mXi4RFMRej9A..|log|originated from User-Agent: Z 3.7.30891 r30851 Jul 12 08:12:00 sip kamailio[22303]: INFO: <script>: [R-ATTEMPT-AUTHORIZATION:v51-8AifZ2mXi4RFMRej9A..] -> In authentication for INVITE against 923135082344@sip.talkhomeappcall.com Jul 12 08:12:00 sip kamailio[22303]: INFO: <script>: [R-ATTEMPT-AUTHORIZATION:v51-8AifZ2mXi4RFMRej9A..] -> got password: e5ef068edf311111111000002124bf90 from cache against 923135082344@sip.talkhomeappcall.com Jul 12 08:12:00 sip kamailio[22303]: DEBUG: auth [auth_mod.c:847]: w_pv_auth_check(): realm [sip.talkhomeappcall.com] flags [1] checks [1] Jul 12 08:12:00 sip kamailio[22303]: DEBUG: auth [api.c:88]: pre_auth(): digest-algo: MD5 parsed value: 1 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: auth [api.c:292]: auth_check_response(): Our result = 'bae0c3bad25ef6951fcc9142dbf6e29c' Jul 12 08:12:00 sip kamailio[22303]: DEBUG: auth [api.c:299]: auth_check_response(): Authorization is OK Jul 12 08:12:00 sip kamailio[22303]: DEBUG: sl [sl.c:282]: send_reply(): reply in stateless mode (sl) Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/msg_translator.c:159]: check_via_address(): (115.186.137.147, 115.186.137.147, 0) Jul 12 08:12:00 sip kamailio[22303]: DEBUG: registrar [lookup.c:256]: lookup_helper(): contact for [923335550609] found by address Jul 12 08:12:00 sip kamailio[22303]: DEBUG: tm [t_lookup.c:1320]: t_newtran(): msg id=1105 , global msg id=1103 , T on entrance=(nil) Jul 12 08:12:00 sip kamailio[22303]: DEBUG: tm [t_lookup.c:477]: t_lookup_request(): start searching: hash=47588, isACK=0 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: tm [t_lookup.c:435]: matching_3261(): RFC3261 transaction matching failed Jul 12 08:12:00 sip kamailio[22303]: DEBUG: tm [t_lookup.c:659]: t_lookup_request(): no transaction found Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/md5utils.c:67]: MD5StringArray(): MD5 calculated: c598ebabb2493d5c9aebf673208c6bea Jul 12 08:12:00 sip kamailio[22303]: DEBUG: tsilo [ts_store.c:80]: ts_store(): storing transaction 47588:281286645 for r-uri: 923335550609 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: tsilo [ts_hash.c:263]: insert_ts_urecord(): urecord entry 0x7f3ac4daaad8 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: tsilo [ts_handlers.c:56]: ts_set_tm_callbacks(): registered TMCB for transaction 47588:281286645 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: tsilo [ts_store.c:103]: ts_store(): transaction 47588:281286645 (ruri: 923335550609) inserted Jul 12 08:12:00 sip kamailio[22303]: DEBUG: htable [ht_var.c:90]: pv_set_ht_cell(): set value for $sht(vtp=>stored::923335550609) Jul 12 08:12:00 sip kamailio[22303]: INFO: <script>: [USER-LOOKUP:v51-8AifZ2mXi4RFMRej9A..] -> stored transaction [47588:281286645] 923135082344=> 923335550609 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: tm [t_lookup.c:1320]: t_newtran(): msg id=1105 , global msg id=1105 , T on entrance=0x7f3ac5004448 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: tm [t_lookup.c:1324]: t_newtran(): transaction already in process 0x7f3ac5004448 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/msg_translator.c:424]: clen_builder(): content-length: 321 (321) Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/msg_translator.c:159]: check_via_address(): (115.186.137.147, 115.186.137.147, 0) Jul 12 08:12:00 sip kamailio[22303]: DEBUG: tm [t_funcs.c:372]: t_relay_to(): new transaction forwarded Jul 12 08:12:00 sip kamailio[22303]: DEBUG: http_async_client [async_http.c:731]: header_list_add(): stored new http header: [User-Agent: testheader] Jul 12 08:12:00 sip kamailio[22303]: DEBUG: http_async_client [async_http.c:731]: header_list_add(): stored new http header: [Host: app.com] Jul 12 08:12:00 sip kamailio[22303]: DEBUG: http_async_client [async_http.c:731]: header_list_add(): stored new http header: [Authorization: Basic NDQ3N00000000000011111TQ=] Jul 12 08:12:00 sip kamailio[22303]: DEBUG: http_async_client [async_http.c:731]: header_list_add(): stored new http header: [Content-Type: application/json] Jul 12 08:12:00 sip kamailio[22303]: INFO: <script>: To User: 923335550609

From User: 923135082344

Jul 12 08:12:00 sip kamailio[22303]: DEBUG: http_async_client [async_http.c:472]: async_send_query(): transaction suspended [47588:281286645] Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [async_http.c:388]: notification_socket_cb(): query received: [ http://app.com/push/notification/923335550609] (0x7f3ac5048008) Jul 12 08:12:00 sip kamailio[22303]: DEBUG: http_async_client [async_http.c:625]: async_push_query(): query sent [ http://app.com/push/notification/923335550609] (0x7f3ac5048008) to worker 4 Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:423]: new_request(): received query http://app.com/push/notification/923335550609 with timeout 5000, tls_verify_peer 1, tls_verify_host 1 (param=0x7f3ac5048008) Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/receive.c:289]: receive_msg(): request-route executed in: 5910 usec Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:80]: build_hash_key(): received id 0x28b12f0 (8)-> 0x28b12f0 (9) Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:93]: build_hash_key(): hash for 0x28b12f0 is 867 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:119]: build_http_m_cell(): hash id for 0x28b12f0 is 867 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:130]: link_http_m_cell(): linking new cell 0x7f3ac4ff5778 to table 0x7f3ac4fc5418 [867] Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:530]: new_request(): Adding easy 0x28b12f0 to multi 0x289a570 (http://app.com/push/notification/923335550609) Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:53]: multi_timer_cb(): multi_timer_cb: Setting timeout to 1 ms Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil) Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/sdp/sdp.c:794]: free_sdp(): _sdp = 0x7f3ac975eb18 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/sdp/sdp.c:796]: free_sdp(): sdp = 0x7f3ac972e418 Jul 12 08:12:00 sip kamailio[22303]: DEBUG: <core> [core/parser/sdp/sdp.c:798]: free_sdp(): session = 0x7f3ac9729ce0 Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:67]: timer_cb(): timeout on socket -1 Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:53]: multi_timer_cb(): multi_timer_cb: Setting timeout to 1 ms Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:561]: check_multi_info(): REMAINING: 1 Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:67]: timer_cb(): timeout on socket -1 Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:53]: multi_timer_cb(): multi_timer_cb: Setting timeout to 1 ms Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:561]: check_multi_info(): REMAINING: 1 Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:67]: timer_cb(): timeout on socket -1 Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:53]: multi_timer_cb(): multi_timer_cb: Setting timeout to 1 ms Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:561]: check_multi_info(): REMAINING: 1 Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:67]: timer_cb(): timeout on socket -1 Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:53]: multi_timer_cb(): multi_timer_cb: Setting timeout to 3 ms Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:561]: check_multi_info(): REMAINING: 1 Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:67]: timer_cb(): timeout on socket -1 Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:53]: multi_timer_cb(): multi_timer_cb: Setting timeout to 1 ms Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:561]: check_multi_info(): REMAINING: 1 Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:67]: timer_cb(): timeout on socket -1 Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:161]: sock_cb(): socket callback: s=11 e=0x28b12f0 what=OUT Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:179]: sock_cb(): Adding data: OUT Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:80]: build_hash_key(): received id 0x28b12f0 (8)-> 0x28b12f0 (9) Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:93]: build_hash_key(): hash for 0x28b12f0 is 867 Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:157]: http_m_cell_lookup(): http_m_cell with easy=0x28b12f0 found on table entry 867 Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:615]: setsock(): added event 0x28ba160 to socket 11 Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:53]: multi_timer_cb(): multi_timer_cb: Setting timeout to 199 ms Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:561]: check_multi_info(): REMAINING: 1 Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:80]: build_hash_key(): received id 0x28b12f0 (8)-> 0x28b12f0 (9) Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:93]: build_hash_key(): hash for 0x28b12f0 is 867 Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:157]: http_m_cell_lookup(): http_m_cell with easy=0x28b12f0 found on table entry 867 Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:96]: event_cb(): activity 4 on socket 11: action 2 Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:129]: event_cb(): performing action 2 on socket 11 Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:161]: sock_cb(): socket callback: s=11 e=0x28b12f0 what=IN Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:184]: sock_cb(): Changing action from OUT to IN Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:615]: setsock(): added event 0x28ba160 to socket 11 Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:131]: event_cb(): action 2 on socket 11 performed Jul 12 08:12:00 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:561]: check_multi_info(): REMAINING: 1 Jul 12 08:12:01 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:67]: timer_cb(): timeout on socket -1 Jul 12 08:12:01 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:561]: check_multi_info(): REMAINING: 1 Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): received on udp socket: (118/100/635) [[SIP/2.0 180 Ringing 0D 0A CSeq: 2 INVITE 0D 0A Call-ID: v51-8AifZ2mXi4RFMRej9A.. 0D 0A From: <sip:923135082344@sip.]] Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP Reply (status): Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg(): version: <SIP/2.0> Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg(): status: <180> Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg(): reason: <Ringing> Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <2> <INVITE> Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=26d24c34 Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [71]; uri=[ sip:923335550609@sip.talkhomeappcall.com;transport=UDP] Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [< sip:923335550609@sip.talkhomeappcall.com;transport=UDP>] Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK4e9b.c598ebabb2493d5c9aebf673208c6bea.0>; state=9 Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): parsing via: next via Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, <rport> = <61717>; state=6 Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-524287-1---6a391e4fb0f8a8f6>; state=16 Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): Via found, flags=2 Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): this is the first via Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/receive.c:205]: receive_msg(): --- received sip message - reply - call-id: [v51-8AifZ2mXi4RFMRej9A..] - cseq: [2 INVITE] Jul 12 08:12:01 sip kamailio[22302]: DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7f3ac975e930) id=1137 global id=1135 T start=(nil) Jul 12 08:12:01 sip kamailio[22302]: DEBUG: tm [t_lookup.c:897]: t_reply_matching(): t_reply_matching: hash 47588 label 0 branch 0 Jul 12 08:12:01 sip kamailio[22302]: DEBUG: tm [t_lookup.c:951]: t_reply_matching(): reply (0x7f3ac975e930) matched an active transaction (T=0x7f3ac5004448)! Jul 12 08:12:01 sip kamailio[22302]: DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg (0x7f3ac975e930) id=1137 global id=1137 T end=0x7f3ac5004448 Jul 12 08:12:01 sip kamailio[22302]: DEBUG: tm [t_reply.c:2207]: reply_received(): org. status uas=0, uac[0]=0 local=0 is_invite=1) Jul 12 08:12:01 sip kamailio[22302]: INFO: <script>: [R-EXTERNAL_REPLY:v51-8AifZ2mXi4RFMRej9A..] -> saw reply to METHOD:INVITE RESPONSE:'180 Ringing' from 115.186.137.147:5060 Jul 12 08:12:01 sip kamailio[22302]: DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7f3ac975e930) id=1137 global id=1137 T start=0x7f3ac5004448 Jul 12 08:12:01 sip kamailio[22302]: DEBUG: tm [t_lookup.c:1091]: t_check_msg(): T (0x7f3ac5004448) already found for msg (0x7f3ac975e930)! Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0 Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/socket_info.c:564]: grep_sock_info(): checking if host==us: 13==12 && [18.130.57.226] == [172.31.21.87] Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/socket_info.c:583]: grep_sock_info(): checking advertise if host==us: 13==13 && [18.130.57.226] == [18.130.57.226] Jul 12 08:12:01 sip kamailio[22302]: DEBUG: textops [textops.c:3063]: has_body_helper(): content length is zero Jul 12 08:12:01 sip kamailio[22302]: DEBUG: tm [t_reply.c:1263]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=180 Jul 12 08:12:01 sip kamailio[22302]: DEBUG: tm [t_reply.c:1786]: relay_reply(): branch=0, save=0, relay=0 icode=0 Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/msg_translator.c:2265]: generate_res_buf_from_sip_res(): old size: 635, new size: 552 Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/msg_translator.c:2283]: generate_res_buf_from_sip_res(): copied size: orig:573, new: 490, rest: 62 msg=#012SIP/2.0 180 Ringing#015#012CSeq: 2 INVITE#015#012Call-ID: v51-8AifZ2mXi4RFMRej9A..#015#012From: < sip:923135082344@sip.talkhomeappcall.com;transport=UDP>;tag=dc4e5a14#015#012To: sip:923335550609@sip.talkhomeappcall.com;transport=UDP;tag=26d24c34#015#012Via: SIP/2.0/UDP 115.186.137.147:61717;rport=61717;branch=z9hG4bK-524287-1---6a391e4fb0f8a8f6#015#012Record-Route: sip:18.130.57.226;lr=on;ftag=dc4e5a14#015#012Contact: "923335550609" sip:923335550609@115.186.137.147:5060;transport=udp;registering_acc=sip_talkhomeappcall_com#015#012User-Agent: Jitsi2.10.5550Windows 10#015#012Content-Length: 0 Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/receive.c:362]: receive_msg(): reply-route executed in: 2261 usec Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil) Jul 12 08:12:01 sip kamailio[22302]: DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): received on udp socket: (118/100/635) [[SIP/2.0 180 Ringing 0D 0A CSeq: 2 INVITE 0D 0A Call-ID: v51-8AifZ2mXi4RFMRej9A.. 0D 0A From: <sip:923135082344@sip.]] Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP Reply (status): Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg(): version: <SIP/2.0> Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg(): status: <180> Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg(): reason: <Ringing> Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <2> <INVITE> Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=26d24c34 Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [71]; uri=[ sip:923335550609@sip.talkhomeappcall.com;transport=UDP] Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [< sip:923335550609@sip.talkhomeappcall.com;transport=UDP>] Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK4e9b.c598ebabb2493d5c9aebf673208c6bea.0>; state=9 Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): parsing via: next via Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, <rport> = <61717>; state=6 Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-524287-1---6a391e4fb0f8a8f6>; state=16 Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): Via found, flags=2 Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): this is the first via Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/receive.c:205]: receive_msg(): --- received sip message - reply - call-id: [v51-8AifZ2mXi4RFMRej9A..] - cseq: [2 INVITE] Jul 12 08:12:01 sip kamailio[22303]: DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7f3ac975e930) id=1106 global id=1105 T start=0xffffffffffffffff Jul 12 08:12:01 sip kamailio[22303]: DEBUG: tm [t_lookup.c:897]: t_reply_matching(): t_reply_matching: hash 47588 label 0 branch 0 Jul 12 08:12:01 sip kamailio[22303]: DEBUG: tm [t_lookup.c:951]: t_reply_matching(): reply (0x7f3ac975e930) matched an active transaction (T=0x7f3ac5004448)! Jul 12 08:12:01 sip kamailio[22303]: DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg (0x7f3ac975e930) id=1106 global id=1106 T end=0x7f3ac5004448 Jul 12 08:12:01 sip kamailio[22303]: DEBUG: tm [t_reply.c:2207]: reply_received(): org. status uas=180, uac[0]=180 local=0 is_invite=1) Jul 12 08:12:01 sip kamailio[22303]: INFO: <script>: [R-EXTERNAL_REPLY:v51-8AifZ2mXi4RFMRej9A..] -> saw reply to METHOD:INVITE RESPONSE:'180 Ringing' from 115.186.137.147:5060 Jul 12 08:12:01 sip kamailio[22303]: DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7f3ac975e930) id=1106 global id=1106 T start=0x7f3ac5004448 Jul 12 08:12:01 sip kamailio[22303]: DEBUG: tm [t_lookup.c:1091]: t_check_msg(): T (0x7f3ac5004448) already found for msg (0x7f3ac975e930)! Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0 Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/socket_info.c:564]: grep_sock_info(): checking if host==us: 13==12 && [18.130.57.226] == [172.31.21.87] Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/socket_info.c:583]: grep_sock_info(): checking advertise if host==us: 13==13 && [18.130.57.226] == [18.130.57.226] Jul 12 08:12:01 sip kamailio[22303]: DEBUG: textops [textops.c:3063]: has_body_helper(): content length is zero Jul 12 08:12:01 sip kamailio[22303]: DEBUG: tm [t_reply.c:1263]: t_should_relay_response(): ->>>>>>>>> T_code=180, new_code=180 Jul 12 08:12:01 sip kamailio[22303]: DEBUG: tm [t_reply.c:1786]: relay_reply(): branch=0, save=0, relay=0 icode=0 Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/msg_translator.c:2265]: generate_res_buf_from_sip_res(): old size: 635, new size: 552 Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/msg_translator.c:2283]: generate_res_buf_from_sip_res(): copied size: orig:573, new: 490, rest: 62 msg=#012SIP/2.0 180 Ringing#015#012CSeq: 2 INVITE#015#012Call-ID: v51-8AifZ2mXi4RFMRej9A..#015#012From: < sip:923135082344@sip.talkhomeappcall.com;transport=UDP>;tag=dc4e5a14#015#012To: sip:923335550609@sip.talkhomeappcall.com;transport=UDP;tag=26d24c34#015#012Via: SIP/2.0/UDP 115.186.137.147:61717;rport=61717;branch=z9hG4bK-524287-1---6a391e4fb0f8a8f6#015#012Record-Route: sip:18.130.57.226;lr=on;ftag=dc4e5a14#015#012Contact: "923335550609" sip:923335550609@115.186.137.147:5060;transport=udp;registering_acc=sip_talkhomeappcall_com#015#012User-Agent: Jitsi2.10.5550Windows 10#015#012Content-Length: 0 Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/receive.c:362]: receive_msg(): reply-route executed in: 2206 usec Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil) Jul 12 08:12:01 sip kamailio[22303]: DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:80]: build_hash_key(): received id 0x28b12f0 (8)-> 0x28b12f0 (9) Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:93]: build_hash_key(): hash for 0x28b12f0 is 867 Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:157]: http_m_cell_lookup(): http_m_cell with easy=0x28b12f0 found on table entry 867 Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:96]: event_cb(): activity 2 on socket 11: action 1 Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:129]: event_cb(): performing action 1 on socket 11 Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:249]: write_cb(): data received: HTTP/1.1 200 OK#015#012 [17] Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:80]: build_hash_key(): received id 0x28b12f0 (8)-> 0x28b12f0 (9) Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:93]: build_hash_key(): hash for 0x28b12f0 is 867 Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:157]: http_m_cell_lookup(): http_m_cell with easy=0x28b12f0 found on table entry 867 Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:289]: write_cb(): getting easy handler info (0x28b12f0) Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:249]: write_cb(): data received: Content-Length: 40#015#012 [20] Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:80]: build_hash_key(): received id 0x28b12f0 (8)-> 0x28b12f0 (9) Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:93]: build_hash_key(): hash for 0x28b12f0 is 867 Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:157]: http_m_cell_lookup(): http_m_cell with easy=0x28b12f0 found on table entry 867 Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:289]: write_cb(): getting easy handler info (0x28b12f0) Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:249]: write_cb(): data received: Content-Type: application/json; charset=utf-8#015#012 [47] Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:80]: build_hash_key(): received id 0x28b12f0 (8)-> 0x28b12f0 (9) Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:93]: build_hash_key(): hash for 0x28b12f0 is 867 Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:157]: http_m_cell_lookup(): http_m_cell with easy=0x28b12f0 found on table entry 867 Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:289]: write_cb(): getting easy handler info (0x28b12f0) Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:249]: write_cb(): data received: Server: Microsoft-HTTPAPI/2.0#015#012 [31] Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:80]: build_hash_key(): received id 0x28b12f0 (8)-> 0x28b12f0 (9) Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:93]: build_hash_key(): hash for 0x28b12f0 is 867 Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:157]: http_m_cell_lookup(): http_m_cell with easy=0x28b12f0 found on table entry 867 Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:289]: write_cb(): getting easy handler info (0x28b12f0) Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:249]: write_cb(): data received: Date: Thu, 12 Jul 2018 08:12:51 GMT#015#012 [37] Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:80]: build_hash_key(): received id 0x28b12f0 (8)-> 0x28b12f0 (9) Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:93]: build_hash_key(): hash for 0x28b12f0 is 867 Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:157]: http_m_cell_lookup(): http_m_cell with easy=0x28b12f0 found on table entry 867 Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:289]: write_cb(): getting easy handler info (0x28b12f0) Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:249]: write_cb(): data received: #015#012 [2] Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:80]: build_hash_key(): received id 0x28b12f0 (8)-> 0x28b12f0 (9) Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:93]: build_hash_key(): hash for 0x28b12f0 is 867 Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:157]: http_m_cell_lookup(): http_m_cell with easy=0x28b12f0 found on table entry 867 Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:289]: write_cb(): getting easy handler info (0x28b12f0) Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:249]: write_cb(): data received: {"message":"Message","status":"Success"} [40] Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:80]: build_hash_key(): received id 0x28b12f0 (8)-> 0x28b12f0 (9) Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:93]: build_hash_key(): hash for 0x28b12f0 is 867 Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:157]: http_m_cell_lookup(): http_m_cell with easy=0x28b12f0 found on table entry 867 Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:289]: write_cb(): getting easy handler info (0x28b12f0) Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:161]: sock_cb(): socket callback: s=11 e=0x28b12f0 what=REMOVE Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:166]: sock_cb(): freeing event 0x28ba160 Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:131]: event_cb(): action 1 on socket 11 performed Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:561]: check_multi_info(): REMAINING: 0 Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:568]: check_multi_info(): DONE: http://app.com/push/notification/923335550609 => (0) Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:80]: build_hash_key(): received id 0x28b12f0 (8)-> 0x28b12f0 (9) Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:93]: build_hash_key(): hash for 0x28b12f0 is 867 Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [hm_hash.c:157]: http_m_cell_lookup(): http_m_cell with easy=0x28b12f0 found on table entry 867 Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [async_http.c:162]: async_http_cb(): query result = HTTP/1.1 200 OK#015#012Content-Length: 40#015#012Content-Type: application/json; charset=utf-8#015#012Server: Microsoft-HTTPAPI/2.0#015#012Date: Thu, 12 Jul 2018 08:12:51 GMT#015#012#015#012{"message":"Message","status":"Success"} [194] Jul 12 08:12:02 sip kamailio[22321]: DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP Reply (status): Jul 12 08:12:02 sip kamailio[22321]: DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg(): version: <HTTP/1.1> Jul 12 08:12:02 sip kamailio[22321]: DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg(): status: <200> Jul 12 08:12:02 sip kamailio[22321]: DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg(): reason: <OK> Jul 12 08:12:02 sip kamailio[22321]: DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=40 Jul 12 08:12:02 sip kamailio[22321]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [async_http.c:209]: async_http_cb(): successfully parsed http reply 0x7f3ac975e930 Jul 12 08:12:02 sip kamailio[22321]: DEBUG: tm [t_lookup.c:1585]: t_lookup_ident(): transaction found Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [async_http.c:241]: async_http_cb(): resuming transaction (47588:281286645) Jul 12 08:12:02 sip kamailio[22321]: DEBUG: tm [t_lookup.c:1585]: t_lookup_ident(): transaction found Jul 12 08:12:02 sip kamailio[22321]: INFO: <script>: [PUSH-HTTP-REPLY:v51-8AifZ2mXi4RFMRej9A..] -> status 200 Jul 12 08:12:02 sip kamailio[22321]: INFO: <script>: [PUSH-HTTP-REPLY:v51-8AifZ2mXi4RFMRej9A..] -> body {"message":"Message","status":"Success"} Jul 12 08:12:02 sip kamailio[22321]: INFO: <script>: [PUSH-HTTP-REPLY:v51-8AifZ2mXi4RFMRej9A..] -> v51-8AifZ2mXi4RFMRej9A..|end|issued has successfully send push notification Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [async_http.h:135]: free_async_query(): freeing query 0x7f3ac5048008 Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:579]: check_multi_info(): reply: [200] HTTP/1.1 200 OK#015#012Content-Length: 40#015#012Content-Type: application/json; charset=utf-8#015#012Server: Microsoft-HTTPAPI/2.0#015#012Date: Thu, 12 Jul 2018 08:12:51 GMT#015#012#015#012{"message":"Message","status":"Success"} [194] Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:584]: check_multi_info(): cleaning up cell 0x7f3ac4ff5778 Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:589]: check_multi_info(): Removing handle 0x28b12f0 Jul 12 08:12:02 sip kamailio[22321]: DEBUG: http_async_client [http_multi.c:147]: event_cb(): last transfer done, kill timeout Jul 12 08:12:02 sip kamailio[22336]: DEBUG: <core> [core/io_wait.h:602]: io_watch_del(): DBG: io_watch_del (0xa53880, 107, -1, 0x0) fd_no=45 called Jul 12 08:12:02 sip kamailio[22336]: DEBUG: <core> [core/tcp_main.c:4196]: handle_tcpconn_ev(): sending to child, events 1 Jul 12 08:12:02 sip kamailio[22336]: DEBUG: <core> [core/tcp_main.c:3878]: send2child(): selected tcp worker 4 31(22332) for activity on [tls: 172.31.21.87:5061], 0x7f3ac504ba10 Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/tcp_read.c:1740]: handle_io(): received n=8 con=0x7f3ac504ba10, fd=12 Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/tcp_read.c:1540]: tcp_read_req(): content-length=287 Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): SIP Request: Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg(): method: <PUBLISH> Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/parser/msg_parser.c:608]: parse_msg(): uri: < sip:447825152591@sip.talkhomeappcall.com;transport=TLS> Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): version: <SIP/2.0> Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-524287-1---97bfb6537506e53b>; state=16 Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): Via found, flags=2 Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): this is the first via Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10 Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [58]; uri=[ sip:447825152591@sip.talkhomeappcall.com;transport=TLS] Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [< sip:447825152591@sip.talkhomeappcall.com;transport=TLS>#015#012] Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <PUBLISH> Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/receive.c:205]: receive_msg(): --- received sip message - request - call-id: [9k-onV_CLivT1AJd9PfB1A..] - cseq: [1 PUBLISH] Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/receive.c:248]: receive_msg(): preparing to run routing scripts... Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=287 Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=eb6f1d48 Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 Jul 12 08:12:02 sip kamailio[22332]: DEBUG: sanity [sanity_mod.c:256]: w_sanity_check(): sanity checks result: 1 Jul 12 08:12:02 sip kamailio[22332]: DEBUG: maxfwd [mf_funcs.c:74]: is_maxfwd_present(): value = 70 Jul 12 08:12:02 sip kamailio[22332]: DEBUG: maxfwd [maxfwd.c:148]: process_maxfwd_header(): value 70 decreased to 50 Jul 12 08:12:02 sip kamailio[22332]: DEBUG: siputils [sipops.c:159]: is_first_hop(): no 2nd via found - first hop Jul 12 08:12:02 sip kamailio[22332]: DEBUG: textops [textops.c:3083]: has_body_helper(): content type is 196613 Jul 12 08:12:02 sip kamailio[22332]: DEBUG: siputils [checks.c:120]: has_totag(): no totag Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/msg_translator.c:159]: check_via_address(): (115.186.137.147, 192.168.0.104, 0) Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/tcp_main.c:2226]: tcpconn_send_put(): send from reader (22332 (31)), reusing fd Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/tcp_main.c:2460]: tcpconn_do_send(): sending... Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/tcp_main.c:2494]: tcpconn_do_send(): after real write: c= 0x7f3ac504ba10 n=421 fd=12 Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/tcp_main.c:2495]: tcpconn_do_send(): buf=#012#027#003#001#001�#026-�Jz�8(+è#015��C��G#036�=�#012{��#033[!��#031[#0015#036��$�#027#020#016<�!S�v-��J�f�#021�*��P(��nE�#017#001��EY#031띪+�n�����<%#023a�R�Cs#030�HR�k ��ɠ���G�M��:#012\b>�u�%����������?��#003e�a�Dv&%��-��X�y^ў#002cs#020l��2#033#025#037��U#001�`#027����#002q#016ޑH��/M7�!#014b�Y��#014;�[�$��Ω#012keRN�#013Y#030a#017��#031���#030�#032(�6#013ԭ�#001�#020�x#003#016[��gd6#035�t�XH#026���#032�+��i� �<�?�_�#033�WCa���?�B��|`'|�� Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/receive.c:289]: receive_msg(): request-route executed in: 1841 usec Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil) Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up Jul 12 08:12:02 sip kamailio[22332]: DEBUG: <core> [core/io_wait.h:380]: io_watch_add(): DBG: io_watch_add(0xa9cf40, 12, 2, 0x7f3ac504ba10), fd_no=1 Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): received on udp socket: (118/100/635) [[SIP/2.0 180 Ringing 0D 0A CSeq: 2 INVITE 0D 0A Call-ID: v51-8AifZ2mXi4RFMRej9A.. 0D 0A From: <sip:923135082344@sip.]] Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP Reply (status): Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg(): version: <SIP/2.0> Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg(): status: <180> Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg(): reason: <Ringing> Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <2> <INVITE> Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=26d24c34 Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [71]; uri=[ sip:923335550609@sip.talkhomeappcall.com;transport=UDP] Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [< sip:923335550609@sip.talkhomeappcall.com;transport=UDP>] Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK4e9b.c598ebabb2493d5c9aebf673208c6bea.0>; state=9 Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): parsing via: next via Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, <rport> = <61717>; state=6 Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-524287-1---6a391e4fb0f8a8f6>; state=16 Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): Via found, flags=2 Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): this is the first via Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/receive.c:205]: receive_msg(): --- received sip message - reply - call-id: [v51-8AifZ2mXi4RFMRej9A..] - cseq: [2 INVITE] Jul 12 08:12:02 sip kamailio[22302]: DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7f3ac975e930) id=1138 global id=1137 T start=0xffffffffffffffff Jul 12 08:12:02 sip kamailio[22302]: DEBUG: tm [t_lookup.c:897]: t_reply_matching(): t_reply_matching: hash 47588 label 0 branch 0 Jul 12 08:12:02 sip kamailio[22302]: DEBUG: tm [t_lookup.c:951]: t_reply_matching(): reply (0x7f3ac975e930) matched an active transaction (T=0x7f3ac5004448)! Jul 12 08:12:02 sip kamailio[22302]: DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg (0x7f3ac975e930) id=1138 global id=1138 T end=0x7f3ac5004448 Jul 12 08:12:02 sip kamailio[22302]: DEBUG: tm [t_reply.c:2207]: reply_received(): org. status uas=180, uac[0]=180 local=0 is_invite=1) Jul 12 08:12:02 sip kamailio[22302]: INFO: <script>: [R-EXTERNAL_REPLY:v51-8AifZ2mXi4RFMRej9A..] -> saw reply to METHOD:INVITE RESPONSE:'180 Ringing' from 115.186.137.147:5060 Jul 12 08:12:02 sip kamailio[22302]: DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7f3ac975e930) id=1138 global id=1138 T start=0x7f3ac5004448 Jul 12 08:12:02 sip kamailio[22302]: DEBUG: tm [t_lookup.c:1091]: t_check_msg(): T (0x7f3ac5004448) already found for msg (0x7f3ac975e930)! Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0 Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/socket_info.c:564]: grep_sock_info(): checking if host==us: 13==12 && [18.130.57.226] == [172.31.21.87] Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/socket_info.c:583]: grep_sock_info(): checking advertise if host==us: 13==13 && [18.130.57.226] == [18.130.57.226] Jul 12 08:12:02 sip kamailio[22302]: DEBUG: textops [textops.c:3063]: has_body_helper(): content length is zero Jul 12 08:12:02 sip kamailio[22302]: DEBUG: tm [t_reply.c:1263]: t_should_relay_response(): ->>>>>>>>> T_code=180, new_code=180 Jul 12 08:12:02 sip kamailio[22302]: DEBUG: tm [t_reply.c:1786]: relay_reply(): branch=0, save=0, relay=0 icode=0 Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/msg_translator.c:2265]: generate_res_buf_from_sip_res(): old size: 635, new size: 552 Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/msg_translator.c:2283]: generate_res_buf_from_sip_res(): copied size: orig:573, new: 490, rest: 62 msg=#012SIP/2.0 180 Ringing#015#012CSeq: 2 INVITE#015#012Call-ID: v51-8AifZ2mXi4RFMRej9A..#015#012From: < sip:923135082344@sip.talkhomeappcall.com;transport=UDP>;tag=dc4e5a14#015#012To: sip:923335550609@sip.talkhomeappcall.com;transport=UDP;tag=26d24c34#015#012Via: SIP/2.0/UDP 115.186.137.147:61717;rport=61717;branch=z9hG4bK-524287-1---6a391e4fb0f8a8f6#015#012Record-Route: sip:18.130.57.226;lr=on;ftag=dc4e5a14#015#012Contact: "923335550609" sip:923335550609@115.186.137.147:5060;transport=udp;registering_acc=sip_talkhomeappcall_com#015#012User-Agent: Jitsi2.10.5550Windows 10#015#012Content-Length: 0 Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/receive.c:362]: receive_msg(): reply-route executed in: 2109 usec Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil) Jul 12 08:12:02 sip kamailio[22302]: DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): received on udp socket: (118/100/635) [[SIP/2.0 180 Ringing 0D 0A CSeq: 2 INVITE 0D 0A Call-ID: v51-8AifZ2mXi4RFMRej9A.. 0D 0A From: <sip:923135082344@sip.]] Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP Reply (status): Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg(): version: <SIP/2.0> Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg(): status: <180> Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg(): reason: <Ringing> Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <2> <INVITE> Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=26d24c34 Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [71]; uri=[ sip:923335550609@sip.talkhomeappcall.com;transport=UDP] Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [< sip:923335550609@sip.talkhomeappcall.com;transport=UDP>] Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK4e9b.c598ebabb2493d5c9aebf673208c6bea.0>; state=9 Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): parsing via: next via Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, <rport> = <61717>; state=6 Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-524287-1---6a391e4fb0f8a8f6>; state=16 Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): Via found, flags=2 Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): this is the first via Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/receive.c:205]: receive_msg(): --- received sip message - reply - call-id: [v51-8AifZ2mXi4RFMRej9A..] - cseq: [2 INVITE] Jul 12 08:12:04 sip kamailio[22303]: DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7f3ac975e930) id=1107 global id=1106 T start=0xffffffffffffffff Jul 12 08:12:04 sip kamailio[22303]: DEBUG: tm [t_lookup.c:897]: t_reply_matching(): t_reply_matching: hash 47588 label 0 branch 0 Jul 12 08:12:04 sip kamailio[22303]: DEBUG: tm [t_lookup.c:951]: t_reply_matching(): reply (0x7f3ac975e930) matched an active transaction (T=0x7f3ac5004448)! Jul 12 08:12:04 sip kamailio[22303]: DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg (0x7f3ac975e930) id=1107 global id=1107 T end=0x7f3ac5004448 Jul 12 08:12:04 sip kamailio[22303]: DEBUG: tm [t_reply.c:2207]: reply_received(): org. status uas=180, uac[0]=180 local=0 is_invite=1) Jul 12 08:12:04 sip kamailio[22303]: INFO: <script>: [R-EXTERNAL_REPLY:v51-8AifZ2mXi4RFMRej9A..] -> saw reply to METHOD:INVITE RESPONSE:'180 Ringing' from 115.186.137.147:5060 Jul 12 08:12:04 sip kamailio[22303]: DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7f3ac975e930) id=1107 global id=1107 T start=0x7f3ac5004448 Jul 12 08:12:04 sip kamailio[22303]: DEBUG: tm [t_lookup.c:1091]: t_check_msg(): T (0x7f3ac5004448) already found for msg (0x7f3ac975e930)! Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0 Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/socket_info.c:564]: grep_sock_info(): checking if host==us: 13==12 && [18.130.57.226] == [172.31.21.87] Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/socket_info.c:583]: grep_sock_info(): checking advertise if host==us: 13==13 && [18.130.57.226] == [18.130.57.226] Jul 12 08:12:04 sip kamailio[22303]: DEBUG: textops [textops.c:3063]: has_body_helper(): content length is zero Jul 12 08:12:04 sip kamailio[22303]: DEBUG: tm [t_reply.c:1263]: t_should_relay_response(): ->>>>>>>>> T_code=180, new_code=180 Jul 12 08:12:04 sip kamailio[22303]: DEBUG: tm [t_reply.c:1786]: relay_reply(): branch=0, save=0, relay=0 icode=0 Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/msg_translator.c:2265]: generate_res_buf_from_sip_res(): old size: 635, new size: 552 Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/msg_translator.c:2283]: generate_res_buf_from_sip_res(): copied size: orig:573, new: 490, rest: 62 msg=#012SIP/2.0 180 Ringing#015#012CSeq: 2 INVITE#015#012Call-ID: v51-8AifZ2mXi4RFMRej9A..#015#012From: < sip:923135082344@sip.talkhomeappcall.com;transport=UDP>;tag=dc4e5a14#015#012To: sip:923335550609@sip.talkhomeappcall.com;transport=UDP;tag=26d24c34#015#012Via: SIP/2.0/UDP 115.186.137.147:61717;rport=61717;branch=z9hG4bK-524287-1---6a391e4fb0f8a8f6#015#012Record-Route: sip:18.130.57.226;lr=on;ftag=dc4e5a14#015#012Contact: "923335550609" sip:923335550609@115.186.137.147:5060;transport=udp;registering_acc=sip_talkhomeappcall_com#015#012User-Agent: Jitsi2.10.5550Windows 10#015#012Content-Length: 0 Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/receive.c:362]: receive_msg(): reply-route executed in: 1784 usec Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil) Jul 12 08:12:04 sip kamailio[22303]: DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up Jul 12 08:12:08 sip kamailio[22332]: DEBUG: <core> [core/io_wait.h:602]: io_watch_del(): DBG: io_watch_del (0xa9cf40, 12, -1, 0x10) fd_no=2 called Jul 12 08:12:08 sip kamailio[22332]: DEBUG: <core> [core/tcp_read.c:1664]: release_tcpconn(): releasing con 0x7f3ac504ba10, state 1, fd=12, id=6 ([115.186.137.147]:54391 -> [115.186.137.147]:5061) Jul 12 08:12:08 sip kamailio[22332]: DEBUG: <core> [core/tcp_read.c:1665]: release_tcpconn(): extra_data 0x7f3ac5048f40 Jul 12 08:12:08 sip kamailio[22336]: DEBUG: <core> [core/tcp_main.c:3308]: handle_tcp_child(): reader response= 7f3ac504ba10, 1 from 4 Jul 12 08:12:08 sip kamailio[22336]: DEBUG: <core> [core/io_wait.h:380]: io_watch_add(): DBG: io_watch_add(0xa53880, 107, 2, 0x7f3ac504ba10), fd_no=44 Jul 12 08:12:08 sip kamailio[22336]: DEBUG: <core> [core/tcp_main.c:3435]: handle_tcp_child(): CONN_RELEASE 0x7f3ac504ba10 refcnt= 1 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): received on udp socket: (106/100/660) [[CANCEL sip:923335550609@sip.talkhomeappcall.com;transport=UDP SIP/2.0 0D 0A Via: SIP/2.0/UDP 115.186.137.]] Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): SIP Request: Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg(): method: <CANCEL> Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:608]: parse_msg(): uri: < sip:923335550609@sip.talkhomeappcall.com;transport=UDP> Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): version: <SIP/2.0> Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-524287-1---6a391e4fb0f8a8f6>; state=16 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): Via found, flags=2 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): this is the first via Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [58]; uri=[ sip:923335550609@sip.talkhomeappcall.com;transport=UDP] Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [< sip:923335550609@sip.talkhomeappcall.com;transport=UDP>#015#012] Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <2> <CANCEL> Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/receive.c:205]: receive_msg(): --- received sip message - request - call-id: [v51-8AifZ2mXi4RFMRej9A..] - cseq: [2 CANCEL] Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/receive.c:248]: receive_msg(): preparing to run routing scripts... Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=dc4e5a14 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: sanity [sanity_mod.c:256]: w_sanity_check(): sanity checks result: 1 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: maxfwd [mf_funcs.c:74]: is_maxfwd_present(): value = 70 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: maxfwd [maxfwd.c:148]: process_maxfwd_header(): value 70 decreased to 50 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: siputils [sipops.c:159]: is_first_hop(): no 2nd via found - first hop Jul 12 08:12:09 sip kamailio[22302]: DEBUG: textops [textops.c:3063]: has_body_helper(): content length is zero Jul 12 08:12:09 sip kamailio[22302]: DEBUG: siputils [checks.c:120]: has_totag(): no totag Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:711]: t_lookupOriginalT(): searching on hash entry 47588 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:420]: matching_3261(): RFC3261 transaction matched, tid=-524287-1---6a391e4fb0f8a8f6 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:807]: t_lookupOriginalT(): canceled transaction found (0x7f3ac5004448)! Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:810]: t_lookupOriginalT(): found - lookup completed Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [tm.c:1091]: ki_t_lookup_cancel_flags(): lookup_original: t_lookupOriginalT returned: 0x7f3ac5004448 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:1320]: t_newtran(): msg id=1139 , global msg id=1138 , T on entrance=0xffffffffffffffff Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:477]: t_lookup_request(): start searching: hash=47588, isACK=0 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:435]: matching_3261(): RFC3261 transaction matching failed Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:659]: t_lookup_request(): no transaction found Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/md5utils.c:67]: MD5StringArray(): MD5 calculated: c598ebabb2493d5c9aebf673208c6bea Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:711]: t_lookupOriginalT(): searching on hash entry 47588 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:420]: matching_3261(): RFC3261 transaction matched, tid=-524287-1---6a391e4fb0f8a8f6 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:807]: t_lookupOriginalT(): canceled transaction found (0x7f3ac5004448)! Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:810]: t_lookupOriginalT(): found - lookup completed Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_cancel.c:335]: cancel_branch(): sending cancel... Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_fwd.c:1426]: e2e_cancel(): e2e cancel proceeding Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/msg_translator.c:159]: check_via_address(): (115.186.137.147, 115.186.137.147, 0) Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_reply.c:1629]: cleanup_uac_timers(): RETR/FR timers reset Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_reply.c:596]: _reply_light(): reply sent out. buf=0x7f3ac9760ba8: SIP/2.0 200 cancelin..., shmem=0x7f3ac4ff5778: SIP/2.0 200 cancelin Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_reply.c:606]: _reply_light(): finished Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_funcs.c:372]: t_relay_to(): new transaction forwarded Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/receive.c:289]: receive_msg(): request-route executed in: 3428 usec Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil) Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): received on udp socket: (118/100/486) [[SIP/2.0 200 OK 0D 0A CSeq: 2 CANCEL 0D 0A Call-ID: v51-8AifZ2mXi4RFMRej9A.. 0D 0A From: <sip:923135082344@sip.talkh]] Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP Reply (status): Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg(): version: <SIP/2.0> Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg(): status: <200> Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg(): reason: <OK> Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <2> <CANCEL> Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=26d24c34 Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [71]; uri=[ sip:923335550609@sip.talkhomeappcall.com;transport=UDP] Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [< sip:923335550609@sip.talkhomeappcall.com;transport=UDP>] Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK4e9b.c598ebabb2493d5c9aebf673208c6bea.0>; state=16 Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): Via found, flags=2 Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): this is the first via Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/receive.c:205]: receive_msg(): --- received sip message - reply - call-id: [v51-8AifZ2mXi4RFMRej9A..] - cseq: [2 CANCEL] Jul 12 08:12:09 sip kamailio[22303]: DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7f3ac975e930) id=1108 global id=1107 T start=0xffffffffffffffff Jul 12 08:12:09 sip kamailio[22303]: DEBUG: tm [t_lookup.c:897]: t_reply_matching(): t_reply_matching: hash 47588 label 0 branch 0 Jul 12 08:12:09 sip kamailio[22303]: DEBUG: tm [t_lookup.c:951]: t_reply_matching(): reply (0x7f3ac975e930) matched an active transaction (T=0x7f3ac5004448)! Jul 12 08:12:09 sip kamailio[22303]: DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg (0x7f3ac975e930) id=1108 global id=1108 T end=0x7f3ac5004448 Jul 12 08:12:09 sip kamailio[22303]: DEBUG: tm [t_reply.c:2207]: reply_received(): org. status uas=180, uac[0]=180 local=0 is_invite=1) Jul 12 08:12:09 sip kamailio[22303]: DEBUG: tm [t_reply.c:2220]: reply_received(): reply to local CANCEL processed Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/receive.c:362]: receive_msg(): reply-route executed in: 752 usec Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil) Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil) Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): received on udp socket: (118/100/591) [[SIP/2.0 487 Request Terminated 0D 0A CSeq: 2 INVITE 0D 0A Call-ID: v51-8AifZ2mXi4RFMRej9A.. 0D 0A From: <sip:923135]] Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP Reply (status): Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg(): version: <SIP/2.0> Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg(): status: <487> Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg(): reason: <Request Terminated> Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <2> <INVITE> Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=26d24c34 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [71]; uri=[ sip:923335550609@sip.talkhomeappcall.com;transport=UDP] Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [< sip:923335550609@sip.talkhomeappcall.com;transport=UDP>] Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK4e9b.c598ebabb2493d5c9aebf673208c6bea.0>; state=9 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): parsing via: next via Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, <rport> = <61717>; state=6 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-524287-1---6a391e4fb0f8a8f6>; state=16 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): Via found, flags=2 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): this is the first via Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/receive.c:205]: receive_msg(): --- received sip message - reply - call-id: [v51-8AifZ2mXi4RFMRej9A..] - cseq: [2 INVITE] Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7f3ac975e930) id=1140 global id=1139 T start=0xffffffffffffffff Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:897]: t_reply_matching(): t_reply_matching: hash 47588 label 0 branch 0 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:951]: t_reply_matching(): reply (0x7f3ac975e930) matched an active transaction (T=0x7f3ac5004448)! Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg (0x7f3ac975e930) id=1140 global id=1140 T end=0x7f3ac5004448 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_reply.c:2207]: reply_received(): org. status uas=180, uac[0]=180 local=0 is_invite=1) Jul 12 08:12:09 sip kamailio[22302]: INFO: <script>: [R-EXTERNAL_REPLY:v51-8AifZ2mXi4RFMRej9A..] -> saw reply to METHOD:INVITE RESPONSE:'487 Request Terminated' from 115.186.137.147:5060 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7f3ac975e930) id=1140 global id=1140 T start=0x7f3ac5004448 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:1091]: t_check_msg(): T (0x7f3ac5004448) already found for msg (0x7f3ac975e930)! Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header Jul 12 08:12:09 sip kamailio[22302]: DEBUG: siputils [sipops.c:171]: is_first_hop(): no record-route header - first hop Jul 12 08:12:09 sip kamailio[22302]: DEBUG: textops [textops.c:3063]: has_body_helper(): content length is zero Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_reply.c:1263]: t_should_relay_response(): ->>>>>>>>> T_code=180, new_code=487 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7f3ac50441b0) id=1104 global id=1104 T start=0x7f3ac5004448 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:1091]: t_check_msg(): T (0x7f3ac5004448) already found for msg (0x7f3ac50441b0)! Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tmx [t_var.c:534]: pv_get_tm_reply_code(): reply code is <487> Jul 12 08:12:09 sip kamailio[22302]: INFO: <script>: v51-8AifZ2mXi4RFMRej9A..|start|external failure route, 487 generated for method INVITE after progress Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/msg_translator.c:159]: check_via_address(): (115.186.137.147, 115.186.137.147, 0) *Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_reply.c:1629]: cleanup_uac_timers(): RETR/FR timers reset* *Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_reply.c:596]: _reply_light(): reply sent out. buf=0x7f3ac9760da0: SIP/2.0 500 I'm terr..., shmem=0x7f3ac5025330: SIP/2.0 500 I'm terr* *Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_reply.c:606]: _reply_light(): finished* *Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_reply.c:1786]: relay_reply(): branch=0, save=0, relay=-1 icode=0* *Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_reply.c:1629]: cleanup_uac_timers(): RETR/FR timers reset* *Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/receive.c:362]: receive_msg(): reply-route executed in: 2909 usec* *Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)* *Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)* *Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)* *Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)* *Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)* *Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)* *Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)* *Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): received on udp socket: (106/100/419) [[ACK sip:923335550609@sip.talkhomeappcall.com sip%3A923335550609@sip.talkhomeappcall.com;transport=UDP SIP/2.0 0D 0A Via: SIP/2.0/UDP 115.186.137.147]]* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): SIP Request:* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg(): method: <ACK>* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:608]: parse_msg(): uri: <sip:923335550609@sip.talkhomeappcall.com sip%3A923335550609@sip.talkhomeappcall.com;transport=UDP>* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): version: <SIP/2.0>* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-524287-1---6a391e4fb0f8a8f6>; state=16* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): Via found, flags=2* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): this is the first via* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=9fe2d4c84d97a4af81aa65ca8fc51b3d-9b76* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [100]; uri=[sip:923335550609@sip.talkhomeappcall.com sip%3A923335550609@sip.talkhomeappcall.com;transport=UDP]* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [<sip:923335550609@sip.talkhomeappcall.com sip%3A923335550609@sip.talkhomeappcall.com;transport=UDP>]* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <2> <ACK>* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/receive.c:205]: receive_msg(): --- received sip message - request - call-id: [v51-8AifZ2mXi4RFMRej9A..] - cseq: [2 ACK]* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/receive.c:248]: receive_msg(): preparing to run routing scripts...* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: sl [sl_funcs.c:387]: sl_filter_ACK(): too late to be a local ACK!* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=dc4e5a14* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: sanity [sanity_mod.c:256]: w_sanity_check(): sanity checks result: 1* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: maxfwd [mf_funcs.c:74]: is_maxfwd_present(): value = 70* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: maxfwd [maxfwd.c:148]: process_maxfwd_header(): value 70 decreased to 50* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: pv [pv_core.c:966]: pv_get_useragent(): no User-Agent header* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: pv [pv_core.c:966]: pv_get_useragent(): no User-Agent header* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: pv [pv_core.c:966]: pv_get_useragent(): no User-Agent header* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: siputils [sipops.c:159]: is_first_hop(): no 2nd via found - first hop* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: textops [textops.c:3063]: has_body_helper(): content length is zero* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: siputils [checks.c:123]: has_totag(): totag found* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: rr [loose.c:112]: find_first_route(): No Route headers found* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: rr [loose.c:944]: loose_route(): There is no Route HF* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7f3ac975e930) id=1109 global id=1108 T start=0xffffffffffffffff* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: tm [t_lookup.c:477]: t_lookup_request(): start searching: hash=47588, isACK=1* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: tm [t_lookup.c:420]: matching_3261(): RFC3261 transaction matched, tid=-524287-1---6a391e4fb0f8a8f6* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: tm [t_lookup.c:676]: t_lookup_request(): transaction found (T=0x7f3ac5004448)* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg (0x7f3ac975e930) id=1109 global id=1109 T end=0x7f3ac5004448* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: tm [t_reply.c:1629]: cleanup_uac_timers(): RETR/FR timers reset* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/timer.c:575]: timer_add_safe(): timer_add called on an active timer 0x7f3ac50044c8 (0x7f3ac44f3ce0, 0x7f3ac44f3ce0), flags 201* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: tm [t_funcs.c:147]: put_on_wait(): transaction 0x7f3ac5004448 already on wait* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/receive.c:289]: receive_msg(): request-route executed in: 2922 usec* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up* *Jul 12 08:12:10 sip kamailio[22302]: DEBUG: <core> [core/udp_server.c:514]: udp_rcv_loop(): probing packet received from 217.33.40.242 57067*

Thanks for your time.

Best Regards, Aqs

On Thu, 12 Jul 2018 at 12:56, Daniel-Constantin Mierla miconda@gmail.com wrote:

Have you looked at log messages, any errors?

If not, then run with debug=3 in kamailio config and send full log messages for such call.

Cheers, Daniel

On 11.07.18 19:15, Aqs Younas wrote:

Sorry, if i could not explain it well before. I hope below picture will make it clear.

...

is it some configuration issue?

BTW what is the best way to call multiple async functions in kamailio.

Any suggestion is much appreciated.

Best Regards,

Aqs Younas

On Wed, 11 Jul 2018 at 12:39, Daniel-Constantin Mierla miconda@gmail.com wrote:

...

Hello,

On 10.07.18 22:08, Aqs Younas wrote:

Greeting list,

I am using two async functions(http_async_query) in configuration one for authentication and other one for push notifications. I am also using tsilio module to suspend the transaction and resumed it.

I am resetting this flag 'T_ASYNC_SUSPENDED' before suspending the transaction. Everything is working fine except. When caller send CANCEL on the call, kamailio successfully completes sip flow at callee(B party) side but send back below packet towards caller.

what the above statement means? Kamailio forwarded the invite to callee, got 200ok, but sends back the 200 response?

Cheers, Daniel

2018/07/10 19:47:41.125893 172.31.21.87:5060 -> 39.38.156.111:59969 SIP/2.0 500 I'm terribly sorry, server error occurred (1/TM ) Via: SIP/2.0/UDP 39.38.156.111:59969 ;branch=z9hG4bK-524287-1---91c6114330fe6293;rport=59969 To: sip:923335550609@sip.talkhomeappcall.com ;transport=UDP;tag=9fe2d4c84d97a4af81aa65ca8fc51b3d-62cb From: sip:923135082344@sip.talkhomeappcall.com ;transport=UDP;tag=d72eaf4c Call-ID: VkAwxpSgkKSGn5dXaXgn5A.. CSeq: 2 INVITE Content-Length: 0

root@sip:~# kamailio -V version: kamailio 5.1.3 (x86_64/linux) flags: STATS: Off, USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, 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_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. id: unknown compiled on 08:06:26 May 2 2018 with gcc 4.9.2

Could someone please help me out how to fix this. Cancels are handles automatically so, i cannot hardcore anything to resolve it.

Best Regards,

Aqs Younas

---

Kamailio (SER) - Users Mailing Listsr-users@lists.kamailio.orghttps://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users

-- Daniel-Constantin Mierla -- www.asipto.comwww.twitter.com/miconda -- www.linkedin.com/in/miconda Kamailio World Conference -- www.kamailioworld.com

---

Kamailio (SER) - Users Mailing Listsr-users@lists.kamailio.orghttps://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users

-- Daniel-Constantin Mierla -- www.asipto.comwww.twitter.com/miconda -- www.linkedin.com/in/miconda Kamailio World Conference -- www.kamailioworld.com

Thanks for replying. Here are the requested details.

N*OTE: Since, Party B is already registered. So, this transaction is not suspended by using t_suspend(). *

INVITE sent out by the kamailio.

2018/07/13 10:03:39.529954 172.31.21.87:5060 -> 115.186.137.147:5060 INVITE sip:923335550609@192.168.0.102:5060;transport=udp;registering_acc=sip_talkhomeappcall_com SIP/2.0 Record-Route: sip:18.130.57.226;lr=on;ftag=ca4e124a Via: SIP/2.0/UDP 18.130.57.226:5060 ;branch=z9hG4bKb073.59d340ab13783ca3e986b077d8c3cc09.1 Via: SIP/2.0/UDP 192.168.0.102:34264 ;rport=34264;received=115.186.137.147;branch=z9hG4bK-524287-1---d3a65fa7d1d9b7b4 Max-Forwards: 50 Contact: sip:923135082344@115.186.137.147:34264;transport=UDP To: sip:923335550609@sip.talkhomeappcall.com;transport=UDP From: sip:923135082344@sip.talkhomeappcall.com;transport=UDP;tag=ca4e124a Call-ID: rygunB2mU7m1w3mE46c1Ww.. CSeq: 2 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE Content-Type: application/sdp Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-cisco-serviceuri User-Agent: Z 3.7.30891 r30851 Allow-Events: presence, kpml Content-Length: 321

v=0 o=Z 0 0 IN IP4 18.130.57.226 s=Z c=IN IP4 18.130.57.226 t=0 0 m=audio 39698 RTP/AVP 3 110 8 0 97 101 a=rtpmap:3 GSM/8000 a=rtpmap:110 speex/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:97 iLBC/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:97 mode=30 a=fmtp:101 0-16 a=sendrecv a=rtcp:39699

I have defined the flag ' T_ASYNC_SUSPENDED'.

*#!define T_ASYNC_SUSPENDED 5*

Order of call it like below.

1. Call comes 2. Send a http async for authentication. 3. On 200 OK from http I perform user lookup 4. If B party is registered call is send towards it. i) Push notification is sent for further registration against device B.

route[USER_LOOKUP] { send_reply("100", "Trying"); if (is_method("INVITE")) { if (!lookup("location")) { route(SEND_PUSH); }else{ ts_store(); $sht(vtp=>stored::$rU) = 1; xlog("L_INFO","[USER-LOOKUP:$ci] -> stored transaction [$T(id_index):$T(id_label)] $fU=> $rU\n"); t_on_reply("EXTERNAL_REPLY"); t_on_failure("EXTERNAL_FAULT"); t_relay(); route(SEND_PUSH); } } }

5. If B party is not registered PUSH notification is send i) On 200 OK from push notification transaction is suspending like this after setting the flag ' T_ASYNC_SUSPENDED'

# suspend the transaction route[SUSPEND] { * resetflag(T_ASYNC_SUSPENDED);* if(!t_suspend()) { xlog("L_ERR","[R-SUSPEND:$ci] -> failed suspending trasaction [$T(id_index): $T(id_label)]\n"); send_reply("501", "Unknown destination"); exit; } xlog("L_INFO","[R-SUSPEND:$ci] -> suspended transaction [$T(id_index):$T(id_label)] $fU => $rU\n"); $sht(vtp=>join::$rU) = "" + $T(id_index) + ":" +$T(id_label); xlog("L_INFO","[R-SUSPEND:$ci] -> htable key value [$sht(vtp=>join::$rU)]\n"); }

Thanks for your time. Please let me know if any further information is required.

Best Regards, Aqs.

On Fri, 13 Jul 2018 at 13:00, Daniel-Constantin Mierla miconda@gmail.com wrote:

Hello, can you give here the INVITE that is sent out by Kamailio? In the screenshot that you gave in a previous email it was the incoming INVITE.

From the logs, the 487 is matching the first branch, but that should be the one that was suspended, not the outgoing one.

Reading back this email thread, you said:

"I am resetting this flag 'T_ASYNC_SUSPENDED' before suspending the transaction."

How do you do that? Can you list the order of operations that happen, like next?

• INVITE received
• http async for auth
• reset the T_ASYNC_SUSPENDED flag ?!?
• http async for push

Cheers, Daniel

On 12.07.18 10:37, Aqs Younas wrote:

I could not find anything related to error. Below are the full detailed logs. Again thanks for you help.

[...] Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): received on udp socket: (118/100/591) [[SIP/2.0 487 Request Terminated 0D 0A CSeq: 2 INVITE 0D 0A Call-ID: v51-8AifZ2mXi4RFMRej9A.. 0D 0A From: <sip:923135]] Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP Reply (status): Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg(): version: <SIP/2.0> Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg(): status: <487> Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg(): reason: <Request Terminated> Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <2> <INVITE> Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=26d24c34 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [71]; uri=[ sip:923335550609@sip.talkhomeappcall.com;transport=UDP] Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [< sip:923335550609@sip.talkhomeappcall.com;transport=UDP>] Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK4e9b.c598ebabb2493d5c9aebf673208c6bea.0>; state=9 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): parsing via: next via Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 235, <rport> = <61717>; state=6 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-524287-1---6a391e4fb0f8a8f6>; state=16 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): Via found, flags=2 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): this is the first via Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/receive.c:205]: receive_msg(): --- received sip message - reply - call-id: [v51-8AifZ2mXi4RFMRej9A..] - cseq: [2 INVITE] Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7f3ac975e930) id=1140 global id=1139 T start=0xffffffffffffffff Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:897]: t_reply_matching(): t_reply_matching: hash 47588 label 0 branch 0 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:951]: t_reply_matching(): reply (0x7f3ac975e930) matched an active transaction (T=0x7f3ac5004448)! Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg (0x7f3ac975e930) id=1140 global id=1140 T end=0x7f3ac5004448 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_reply.c:2207]: reply_received(): org. status uas=180, uac[0]=180 local=0 is_invite=1) Jul 12 08:12:09 sip kamailio[22302]: INFO: <script>: [R-EXTERNAL_REPLY:v51-8AifZ2mXi4RFMRej9A..] -> saw reply to METHOD:INVITE RESPONSE:'487 Request Terminated' from 115.186.137.147:5060 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7f3ac975e930) id=1140 global id=1140 T start=0x7f3ac5004448 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:1091]: t_check_msg(): T (0x7f3ac5004448) already found for msg (0x7f3ac975e930)! Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header Jul 12 08:12:09 sip kamailio[22302]: DEBUG: siputils [sipops.c:171]: is_first_hop(): no record-route header - first hop Jul 12 08:12:09 sip kamailio[22302]: DEBUG: textops [textops.c:3063]: has_body_helper(): content length is zero Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_reply.c:1263]: t_should_relay_response(): ->>>>>>>>> T_code=180, new_code=487 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7f3ac50441b0) id=1104 global id=1104 T start=0x7f3ac5004448 Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:1091]: t_check_msg(): T (0x7f3ac5004448) already found for msg (0x7f3ac50441b0)! Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tmx [t_var.c:534]: pv_get_tm_reply_code(): reply code is <487> Jul 12 08:12:09 sip kamailio[22302]: INFO: <script>: v51-8AifZ2mXi4RFMRej9A..|start|external failure route, 487 generated for method INVITE after progress Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/msg_translator.c:159]: check_via_address(): (115.186.137.147, 115.186.137.147, 0) *Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_reply.c:1629]: cleanup_uac_timers(): RETR/FR timers reset* *Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_reply.c:596]: _reply_light(): reply sent out. buf=0x7f3ac9760da0: SIP/2.0 500 I'm terr..., shmem=0x7f3ac5025330: SIP/2.0 500 I'm terr* *Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_reply.c:606]: _reply_light(): finished* *Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_reply.c:1786]: relay_reply(): branch=0, save=0, relay=-1 icode=0* *Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_reply.c:1629]: cleanup_uac_timers(): RETR/FR timers reset* *Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/receive.c:362]: receive_msg(): reply-route executed in: 2909 usec* *Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)* *Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)* *Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)* *Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)* *Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)* *Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)* *Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)* *Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): received on udp socket: (106/100/419) [[ACK sip:923335550609@sip.talkhomeappcall.com sip%3A923335550609@sip.talkhomeappcall.com;transport=UDP SIP/2.0 0D 0A Via: SIP/2.0/UDP 115.186.137.147]]* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): SIP Request:* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg(): method: <ACK>* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:608]: parse_msg(): uri: <sip:923335550609@sip.talkhomeappcall.com sip%3A923335550609@sip.talkhomeappcall.com;transport=UDP>* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): version: <SIP/2.0>* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-524287-1---6a391e4fb0f8a8f6>; state=16* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): Via found, flags=2* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): this is the first via* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=9fe2d4c84d97a4af81aa65ca8fc51b3d-9b76* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [100]; uri=[sip:923335550609@sip.talkhomeappcall.com sip%3A923335550609@sip.talkhomeappcall.com;transport=UDP]* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [<sip:923335550609@sip.talkhomeappcall.com sip%3A923335550609@sip.talkhomeappcall.com;transport=UDP>]* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <2> <ACK>* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/receive.c:205]: receive_msg(): --- received sip message - request - call-id: [v51-8AifZ2mXi4RFMRej9A..] - cseq: [2 ACK]* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/receive.c:248]: receive_msg(): preparing to run routing scripts...* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: sl [sl_funcs.c:387]: sl_filter_ACK(): too late to be a local ACK!* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=dc4e5a14* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: sanity [sanity_mod.c:256]: w_sanity_check(): sanity checks result: 1* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: maxfwd [mf_funcs.c:74]: is_maxfwd_present(): value = 70* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: maxfwd [maxfwd.c:148]: process_maxfwd_header(): value 70 decreased to 50* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: pv [pv_core.c:966]: pv_get_useragent(): no User-Agent header* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: pv [pv_core.c:966]: pv_get_useragent(): no User-Agent header* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: pv [pv_core.c:966]: pv_get_useragent(): no User-Agent header* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: siputils [sipops.c:159]: is_first_hop(): no 2nd via found - first hop* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: textops [textops.c:3063]: has_body_helper(): content length is zero* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: siputils [checks.c:123]: has_totag(): totag found* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: rr [loose.c:112]: find_first_route(): No Route headers found* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: rr [loose.c:944]: loose_route(): There is no Route HF* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: tm [t_lookup.c:1019]: t_check_msg(): msg (0x7f3ac975e930) id=1109 global id=1108 T start=0xffffffffffffffff* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: tm [t_lookup.c:477]: t_lookup_request(): start searching: hash=47588, isACK=1* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: tm [t_lookup.c:420]: matching_3261(): RFC3261 transaction matched, tid=-524287-1---6a391e4fb0f8a8f6* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: tm [t_lookup.c:676]: t_lookup_request(): transaction found (T=0x7f3ac5004448)* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: tm [t_lookup.c:1088]: t_check_msg(): msg (0x7f3ac975e930) id=1109 global id=1109 T end=0x7f3ac5004448* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: tm [t_reply.c:1629]: cleanup_uac_timers(): RETR/FR timers reset* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/timer.c:575]: timer_add_safe(): timer_add called on an active timer 0x7f3ac50044c8 (0x7f3ac44f3ce0, 0x7f3ac44f3ce0), flags 201* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: tm [t_funcs.c:147]: put_on_wait(): transaction 0x7f3ac5004448 already on wait* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/receive.c:289]: receive_msg(): request-route executed in: 2922 usec* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)* *Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/receive.c:378]: receive_msg(): cleaning up* *Jul 12 08:12:10 sip kamailio[22302]: DEBUG: <core> [core/udp_server.c:514]: udp_rcv_loop(): probing packet received from 217.33.40.242 57067*

Thanks for your time.

Best Regards, Aqs

On Thu, 12 Jul 2018 at 12:56, Daniel-Constantin Mierla miconda@gmail.com wrote:

...

Have you looked at log messages, any errors?

If not, then run with debug=3 in kamailio config and send full log messages for such call.

Cheers, Daniel

On 11.07.18 19:15, Aqs Younas wrote:

Sorry, if i could not explain it well before. I hope below picture will make it clear.

...

is it some configuration issue?

BTW what is the best way to call multiple async functions in kamailio.

Any suggestion is much appreciated.

Best Regards,

Aqs Younas

On Wed, 11 Jul 2018 at 12:39, Daniel-Constantin Mierla miconda@gmail.com wrote:

...

Hello,

On 10.07.18 22:08, Aqs Younas wrote:

Greeting list,

I am using two async functions(http_async_query) in configuration one for authentication and other one for push notifications. I am also using tsilio module to suspend the transaction and resumed it.

I am resetting this flag 'T_ASYNC_SUSPENDED' before suspending the transaction. Everything is working fine except. When caller send CANCEL on the call, kamailio successfully completes sip flow at callee(B party) side but send back below packet towards caller.

what the above statement means? Kamailio forwarded the invite to callee, got 200ok, but sends back the 200 response?

Cheers, Daniel

2018/07/10 19:47:41.125893 172.31.21.87:5060 -> 39.38.156.111:59969 SIP/2.0 500 I'm terribly sorry, server error occurred (1/TM ) Via: SIP/2.0/UDP 39.38.156.111:59969 ;branch=z9hG4bK-524287-1---91c6114330fe6293;rport=59969 To: sip:923335550609@sip.talkhomeappcall.com ;transport=UDP;tag=9fe2d4c84d97a4af81aa65ca8fc51b3d-62cb From: sip:923135082344@sip.talkhomeappcall.com ;transport=UDP;tag=d72eaf4c Call-ID: VkAwxpSgkKSGn5dXaXgn5A.. CSeq: 2 INVITE Content-Length: 0

root@sip:~# kamailio -V version: kamailio 5.1.3 (x86_64/linux) flags: STATS: Off, USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, 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_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. id: unknown compiled on 08:06:26 May 2 2018 with gcc 4.9.2

Could someone please help me out how to fix this. Cancels are handles automatically so, i cannot hardcore anything to resolve it.

Best Regards,

Aqs Younas

---

Kamailio (SER) - Users Mailing Listsr-users@lists.kamailio.orghttps://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users

-- Daniel-Constantin Mierla -- www.asipto.comwww.twitter.com/miconda -- www.linkedin.com/in/miconda Kamailio World Conference -- www.kamailioworld.com

---

Kamailio (SER) - Users Mailing Listsr-users@lists.kamailio.orghttps://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users

-- Daniel-Constantin Mierla -- www.asipto.comwww.twitter.com/miconda -- www.linkedin.com/in/miconda Kamailio World Conference -- www.kamailioworld.com

---

Kamailio (SER) - Users Mailing Listsr-users@lists.kamailio.orghttps://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users

-- Daniel-Constantin Mierla -- www.asipto.comwww.twitter.com/miconda -- www.linkedin.com/in/miconda Kamailio World Conference -- www.kamailioworld.com

Very unlikely, but may be try playing with the TM's params, like for e.g.

https://kamailio.org/docs/modules/5.1.x/modules/tm.html#remap_503_500

On Thu, Jul 12, 2018 at 2:56 AM Aqs Younas aqsyounas@gmail.com wrote:

Sorry, if i could not explain it well before. I hope below picture will make it clear.

[image: image.png]

is it some configuration issue?

BTW what is the best way to call multiple async functions in kamailio.

Any suggestion is much appreciated.

Best Regards,

Aqs Younas

On Wed, 11 Jul 2018 at 12:39, Daniel-Constantin Mierla miconda@gmail.com wrote:

...

Hello,

On 10.07.18 22:08, Aqs Younas wrote:

Greeting list,

I am using two async functions(http_async_query) in configuration one for authentication and other one for push notifications. I am also using tsilio module to suspend the transaction and resumed it.

I am resetting this flag 'T_ASYNC_SUSPENDED' before suspending the transaction. Everything is working fine except. When caller send CANCEL on the call, kamailio successfully completes sip flow at callee(B party) side but send back below packet towards caller.

what the above statement means? Kamailio forwarded the invite to callee, got 200ok, but sends back the 200 response?

Cheers, Daniel

2018/07/10 19:47:41.125893 172.31.21.87:5060 -> 39.38.156.111:59969 SIP/2.0 500 I'm terribly sorry, server error occurred (1/TM ) Via: SIP/2.0/UDP 39.38.156.111:59969 ;branch=z9hG4bK-524287-1---91c6114330fe6293;rport=59969 To: sip:923335550609@sip.talkhomeappcall.com ;transport=UDP;tag=9fe2d4c84d97a4af81aa65ca8fc51b3d-62cb From: sip:923135082344@sip.talkhomeappcall.com ;transport=UDP;tag=d72eaf4c Call-ID: VkAwxpSgkKSGn5dXaXgn5A.. CSeq: 2 INVITE Content-Length: 0

root@sip:~# kamailio -V version: kamailio 5.1.3 (x86_64/linux) flags: STATS: Off, USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, 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_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. id: unknown compiled on 08:06:26 May 2 2018 with gcc 4.9.2

Could someone please help me out how to fix this. Cancels are handles automatically so, i cannot hardcore anything to resolve it.

Best Regards,

Aqs Younas

---

Kamailio (SER) - Users Mailing Listsr-users@lists.kamailio.orghttps://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users

-- Daniel-Constantin Mierla -- www.asipto.comwww.twitter.com/miconda -- www.linkedin.com/in/miconda Kamailio World Conference -- www.kamailioworld.com

---

Kamailio (SER) - Users Mailing List sr-users@lists.kamailio.org https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users