[sr-dev] [kamailio/kamailio] Problem with CANCEL handling (#1841)
alkorik
notifications at github.com
Thu Feb 7 11:54:15 CET 2019
Hello,
I'm trying to set up kamailio as a simple load balancer proxy between VOIP Providers
and a cluster of asterisk servers.
I have started with the default kamailio.cfg.
At the end, i got this up and running, but with one exception: if incoming
call is not answered by the asterisk end (i.e. it is in ringing state), and
then the gateway sends CANCEL request, kamailio is unable to recognize the
transaction and is not forwarding the request to asterisk. The result is:
the call is left "dangling" in the PBX and is not properly hang up.
I have call flow: Provider 214.22.198.51 -> Kamailio 38.149.172.163 -> Asterisk 38.149.172.164.
**Log from Provider 214.22.198.51**
Reliably Transmitting (no NAT) to 38.149.172.163:5060:
INVITE sip:100 at 38.149.172.163:5060 SIP/2.0
Via: SIP/2.0/UDP 214.22.198.51:5060;branch=z9hG4bK7d220dff
Max-Forwards: 70
From: "testaccount" <sip:123456 at 214.22.198.51>;tag=as5a9816e5
To: <sip:100 at 38.149.172.163:5060>
Contact: <sip:123456 at 214.22.198.51:5060>
Call-ID: 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060
CSeq: 102 INVITE
User-Agent: Asterisk PBX 14.6.2
Date: Thu, 07 Feb 2019 10:45:15 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 310
v=0
o=root 610375704 610375704 IN IP4 214.22.198.51
s=Asterisk PBX 14.6.2
c=IN IP4 214.22.198.51
t=0 0
m=audio 13076 RTP/AVP 18 8 0 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=maxptime:150
a=sendrecv
---
-- Called SIP/kamailio/100
<--- SIP read from UDP:38.149.172.163:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 214.22.198.51:5060;branch=z9hG4bK7d220dff
From: "testaccount" <sip:123456 at 214.22.198.51>;tag=as5a9816e5
To: <sip:100 at 38.149.172.163:5060>
Call-ID: 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060
CSeq: 102 INVITE
Server: kamailio (5.2.0 (x86_64/linux))
Content-Length: 0
<------------->
--- (8 headers 0 lines) ---
<--- SIP read from UDP:38.149.172.163:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 214.22.198.51:5060;branch=z9hG4bK7d220dff
From: "testaccount" <sip:123456 at 214.22.198.51>;tag=as5a9816e5
To: <sip:100 at 38.149.172.163:5060>
Call-ID: 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060
CSeq: 102 INVITE
Server: Asterisk PBX 16.1.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:100 at 38.149.172.164:5060>
Content-Length: 0
<------------->
--- (12 headers 0 lines) ---
<--- SIP read from UDP:38.149.172.163:5060 --->
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 214.22.198.51:5060;branch=z9hG4bK7d220dff
From: "testaccount" <sip:123456 at 214.22.198.51>;tag=as5a9816e5
To: <sip:100 at 38.149.172.163:5060>;tag=as14e62645
Call-ID: 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060
CSeq: 102 INVITE
Server: Asterisk PBX 16.1.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:100 at 38.149.172.164:5060>
Content-Length: 0
<------------->
--- (12 headers 0 lines) ---
sip_route_dump: route/path hop: <sip:100 at 38.149.172.164:5060>
-- SIP/kamailio-0007f2d9 is ringing
Scheduling destruction of SIP dialog '0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060' in 32000 ms (Method: INVITE)
Reliably Transmitting (no NAT) to 38.149.172.163:5060:
CANCEL sip:100 at 38.149.172.163:5060 SIP/2.0
Via: SIP/2.0/UDP 214.22.198.51:5060;branch=z9hG4bK7d220dff
Max-Forwards: 70
From: "testaccount" <sip:123456 at 214.22.198.51>;tag=as5a9816e5
To: <sip:100 at 38.149.172.163:5060>
Call-ID: 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060
CSeq: 102 CANCEL
User-Agent: Asterisk PBX 14.6.2
Content-Length: 0
**Kamailio 38.149.172.163**
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: <core> [core/udp_server.c:492]: udp_rcv_loop(): received on udp socket: (106/100/359) [[CANCEL sip:100 at 38.149.172.163:5060 SIP/2.0 0D 0A Via: SIP/2.0/UDP 214.22.198.51:5060;branch=z9hG4bK7d220d]]
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): SIP Request:
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: <core> [core/parser/msg_parser.c:612]: parse_msg(): method: <CANCEL>
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): uri: <sip:100 at 38.149.172.163:5060>
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg(): version: <SIP/2.0>
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK7d220dff>; state=16
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: <core> [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: <core> [core/parser/msg_parser.c:500]: parse_headers(): this is the first via
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [31]; uri=[sip:100 at 38.149.172.163:5060]
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: <core> [core/parser/msg_parser.c:174]: get_hdr_field(): to body [<sip:100 at 38.149.172.163:5060>
Feb 7 12:45:20 kamailion-ser kamailio: ], to tag []
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <102> <CANCEL>
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: <core> [core/receive.c:245]: receive_msg(): --- received sip message - request - call-id: [0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060] - cseq: [102 CANCEL]
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: <core> [core/parser/msg_parser.c:185]: get_hdr_field(): content_length=0
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} <core> [core/receive.c:295]: receive_msg(): preparing to run routing scripts...
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} maxfwd [mf_funcs.c:74]: is_maxfwd_present(): value = 70
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} sanity [sanity.c:247]: check_ruri_sip_version(): check_ruri_sip_version entered
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} sanity [sanity.c:270]: check_ruri_sip_version(): check_ruri_sip_version passed
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} sanity [sanity.c:277]: check_ruri_scheme(): check_ruri_scheme entered
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} sanity [sanity.c:297]: check_ruri_scheme(): check_ruri_scheme passed
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} sanity [sanity.c:305]: check_required_headers(): check_required_headers entered
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} sanity [sanity.c:313]: check_required_headers(): check_required_headers passed
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} sanity [sanity.c:321]: check_via1_header(): check via1 header
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} sanity [sanity.c:479]: check_cseq_method(): check_cseq_method entered
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} sanity [sanity.c:512]: check_cseq_method(): check_cseq_method passed
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} sanity [sanity.c:521]: check_cseq_value(): check_cseq_value entered
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} sanity [sanity.c:549]: check_cseq_value(): check_cseq_value passed
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} sanity [sanity.c:558]: check_cl(): check_cl entered
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} sanity [sanity.c:583]: check_cl(): check_cl passed
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} sanity [sanity.c:595]: check_expires_value(): check_expires_value entered
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} sanity [sanity.c:632]: check_expires_value(): no expires header found
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} sanity [sanity.c:728]: check_parse_uris(): check_parse_uris entered
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} sanity [sanity.c:732]: check_parse_uris(): parsing ruri
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} sanity [sanity.c:746]: check_parse_uris(): looking up From header
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} sanity [sanity.c:760]: check_parse_uris(): parsing From header
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=as5a9816e5
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} sanity [sanity.c:786]: check_parse_uris(): parsing From URI
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} sanity [sanity.c:804]: check_parse_uris(): looking up To header
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} sanity [sanity.c:826]: check_parse_uris(): check_parse_uris(): parsing To URI
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} sanity [sanity.c:871]: check_parse_uris(): check_parse_uris passed
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} sanity [sanity_mod.c:254]: w_sanity_check(): sanity checks result: 1
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} tm [t_lookup.c:712]: t_lookupOriginalT(): searching on hash entry 23780
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} tm [t_lookup.c:436]: matching_3261(): RFC3261 transaction matching failed
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} tm [t_lookup.c:802]: t_lookupOriginalT(): no CANCEL matching found!
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} tm [t_lookup.c:804]: t_lookupOriginalT(): lookup completed
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} tm [tm.c:1093]: ki_t_lookup_cancel_flags(): lookup_original: t_lookupOriginalT returned: (nil)
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} <core> [core/receive.c:353]: receive_msg(): request-route executed in: 220 usec
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} <core> [core/xavp.c:495]: xavp_destroy_list(): destroying xavp list (nil)
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: {1 102 CANCEL 0891a0e9592a055f2828c0f00af09783 at 214.22.198.51:5060} <core> [core/receive.c:457]: receive_msg(): cleaning up
kamailio -v
version: kamailio 5.2.0 (x86_64/linux) 535e13
flags: STATS: Off, USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, 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_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB
poll method support: poll, epoll_lt, epoll_et, sigio_rt, select.
id: 535e13
compiled on 01:27:51 Dec 16 2018 with gcc 4.8.5
How can i fix this?
Thanks!
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/1841
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/sr-dev/attachments/20190207/d3f44fda/attachment-0001.html>
More information about the sr-dev
mailing list