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.
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(a)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(a)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,
Daniel
2018/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(a)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(a)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(a)lists.kamailio.org
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users