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 mailto:sip%3A923335550609@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 mailto:sip%3A923335550609@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 http://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 mailto: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 mailto: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 mailto: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 mailto: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 mailto: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 <mailto: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, Daniel2018/07/10 19:47:41.125893 172.31.21.87:5060 <http://172.31.21.87:5060> -> 39.38.156.111:59969 <http://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 <mailto:sip%3A923335550609@sip.talkhomeappcall.com>;transport=UDP>;tag=9fe2d4c84d97a4af81aa65ca8fc51b3d-62cb From: <sip:923135082344@sip.talkhomeappcall.com <mailto:sip%3A923135082344@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 List sr-users@lists.kamailio.org <mailto:sr-users@lists.kamailio.org> https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users-- Daniel-Constantin Mierla -- www.asipto.com <http://www.asipto.com> www.twitter.com/miconda <http://www.twitter.com/miconda> -- www.linkedin.com/in/miconda <http://www.linkedin.com/in/miconda> Kamailio World Conference -- www.kamailioworld.com <http://www.kamailioworld.com> _______________________________________________ Kamailio (SER) - Users Mailing List sr-users@lists.kamailio.org <mailto:sr-users@lists.kamailio.org> https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users-- Daniel-Constantin Mierla -- www.asipto.com <http://www.asipto.com> www.twitter.com/miconda <http://www.twitter.com/miconda> -- www.linkedin.com/in/miconda <http://www.linkedin.com/in/miconda> Kamailio World Conference -- www.kamailioworld.com <http://www.kamailioworld.com>
Kamailio (SER) - Users Mailing List sr-users@lists.kamailio.org https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users