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=26d24c34Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29Jul 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=9Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_via.c:2681]: parse_via(): parsing via: next viaJul 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=6Jul 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=16Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): Via found, flags=2Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): this is the first viaJul 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=0xffffffffffffffffJul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_lookup.c:897]: t_reply_matching(): t_reply_matching: hash 47588 label 0 branch 0Jul 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=0x7f3ac5004448Jul 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:5060Jul 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=0x7f3ac5004448Jul 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=0Jul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of headerJul 12 08:12:09 sip kamailio[22302]: DEBUG: siputils [sipops.c:171]: is_first_hop(): no record-route header - first hopJul 12 08:12:09 sip kamailio[22302]: DEBUG: textops [textops.c:3063]: has_body_helper(): content length is zeroJul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_reply.c:1263]: t_should_relay_response(): ->>>>>>>>> T_code=180, new_code=487Jul 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=0x7f3ac5004448Jul 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 progressJul 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 resetJul 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 terrJul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_reply.c:606]: _reply_light(): finishedJul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_reply.c:1786]: relay_reply(): branch=0, save=0, relay=-1 icode=0Jul 12 08:12:09 sip kamailio[22302]: DEBUG: tm [t_reply.c:1629]: cleanup_uac_timers(): RETR/FR timers resetJul 12 08:12:09 sip kamailio[22302]: DEBUG: <core> [core/receive.c:362]: receive_msg(): reply-route executed in: 2909 usecJul 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 upJul 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;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;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=16Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): Via found, flags=2Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): this is the first viaJul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=9fe2d4c84d97a4af81aa65ca8fc51b3d-9b76Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29Jul 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;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/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=0Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of headerJul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=dc4e5a14Jul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29Jul 12 08:12:09 sip kamailio[22303]: DEBUG: sanity [sanity_mod.c:256]: w_sanity_check(): sanity checks result: 1Jul 12 08:12:09 sip kamailio[22303]: DEBUG: maxfwd [mf_funcs.c:74]: is_maxfwd_present(): value = 70Jul 12 08:12:09 sip kamailio[22303]: DEBUG: maxfwd [maxfwd.c:148]: process_maxfwd_header(): value 70 decreased to 50Jul 12 08:12:09 sip kamailio[22303]: DEBUG: pv [pv_core.c:966]: pv_get_useragent(): no User-Agent headerJul 12 08:12:09 sip kamailio[22303]: DEBUG: pv [pv_core.c:966]: pv_get_useragent(): no User-Agent headerJul 12 08:12:09 sip kamailio[22303]: DEBUG: pv [pv_core.c:966]: pv_get_useragent(): no User-Agent headerJul 12 08:12:09 sip kamailio[22303]: DEBUG: siputils [sipops.c:159]: is_first_hop(): no 2nd via found - first hopJul 12 08:12:09 sip kamailio[22303]: DEBUG: textops [textops.c:3063]: has_body_helper(): content length is zeroJul 12 08:12:09 sip kamailio[22303]: DEBUG: siputils [checks.c:123]: has_totag(): totag foundJul 12 08:12:09 sip kamailio[22303]: DEBUG: rr [loose.c:112]: find_first_route(): No Route headers foundJul 12 08:12:09 sip kamailio[22303]: DEBUG: rr [loose.c:944]: loose_route(): There is no Route HFJul 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=0xffffffffffffffffJul 12 08:12:09 sip kamailio[22303]: DEBUG: tm [t_lookup.c:477]: t_lookup_request(): start searching: hash=47588, isACK=1Jul 12 08:12:09 sip kamailio[22303]: DEBUG: tm [t_lookup.c:420]: matching_3261(): RFC3261 transaction matched, tid=-524287-1---6a391e4fb0f8a8f6Jul 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=0x7f3ac5004448Jul 12 08:12:09 sip kamailio[22303]: DEBUG: tm [t_reply.c:1629]: cleanup_uac_timers(): RETR/FR timers resetJul 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 201Jul 12 08:12:09 sip kamailio[22303]: DEBUG: tm [t_funcs.c:147]: put_on_wait(): transaction 0x7f3ac5004448 already on waitJul 12 08:12:09 sip kamailio[22303]: DEBUG: <core> [core/receive.c:289]: receive_msg(): request-route executed in: 2922 usecJul 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 upJul 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:59969SIP/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=59969To: <sip:923335550609@sip.talkhomeappcall.com;transport=UDP>;tag=9fe2d4c84d97a4af81aa65ca8fc51b3d-62cbFrom: <sip:923135082344@sip.talkhomeappcall.com;transport=UDP>;tag=d72eaf4cCall-ID: VkAwxpSgkKSGn5dXaXgn5A..CSeq: 2 INVITEContent-Length: 0
root@sip:~# kamailio -Vversion: 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_RESADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MBpoll method support: poll, epoll_lt, epoll_et, sigio_rt, select.id: unknowncompiled 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 https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
-- Daniel-Constantin Mierla -- www.asipto.com www.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
-- Daniel-Constantin Mierla -- www.asipto.com www.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
-- Daniel-Constantin Mierla -- www.asipto.com www.twitter.com/miconda -- www.linkedin.com/in/miconda Kamailio World Conference -- www.kamailioworld.com