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@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@214.22.198.51;tag=as5a9816e5
To: sip:100@38.149.172.163:5060
Contact: sip:123456@214.22.198.51:5060
Call-ID: 0891a0e9592a055f2828c0f00af09783@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

<------------->
--- (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@214.22.198.51;tag=as5a9816e5
To: sip:100@38.149.172.163:5060
Call-ID: 0891a0e9592a055f2828c0f00af09783@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@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@214.22.198.51;tag=as5a9816e5
To: sip:100@38.149.172.163:5060;tag=as14e62645
Call-ID: 0891a0e9592a055f2828c0f00af09783@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@38.149.172.164:5060
Content-Length: 0

<------------->
--- (12 headers 0 lines) ---
sip_route_dump: route/path hop: sip:100@38.149.172.164:5060
-- SIP/kamailio-0007f2d9 is ringing
Scheduling destruction of SIP dialog '0891a0e9592a055f2828c0f00af09783@214.22.198.51:5060' in 32000 ms (Method: INVITE)
Reliably Transmitting (no NAT) to 38.149.172.163:5060:
CANCEL sip:100@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@214.22.198.51;tag=as5a9816e5
To: sip:100@38.149.172.163:5060
Call-ID: 0891a0e9592a055f2828c0f00af09783@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/udp_server.c:492]: udp_rcv_loop(): received on udp socket: (106/100/359) [[CANCEL sip:100@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/parser/msg_parser.c:610]: parse_msg(): SIP Request:
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: [core/parser/msg_parser.c:612]: parse_msg(): method:
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: [core/parser/msg_parser.c:614]: parse_msg(): uri: sip:100@38.149.172.163:5060
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: [core/parser/msg_parser.c:616]: parse_msg(): version: <SIP/2.0>
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, = ; state=16
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: [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/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: [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/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/parser/msg_parser.c:171]: get_hdr_field(): [31]; uri=[sip:100@38.149.172.163:5060]
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: [core/parser/msg_parser.c:174]: get_hdr_field(): to body [sip:100@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/parser/msg_parser.c:152]: get_hdr_field(): cseq : <102>
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: [core/receive.c:245]: receive_msg(): --- received sip message - request - call-id: [0891a0e9592a055f2828c0f00af09783@214.22.198.51:5060] - cseq: [102 CANCEL]
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: [core/parser/msg_parser.c:185]: get_hdr_field(): content_length=0
Feb 7 12:45:20 kamailion-ser kamailio: 24(22599) DEBUG: [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@214.22.198.51:5060} [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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@214.22.198.51:5060} [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@214.22.198.51:5060} [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@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@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@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@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@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@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@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@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@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@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@214.22.198.51:5060} [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@214.22.198.51:5060} [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@214.22.198.51:5060} [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@214.22.198.51:5060} [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@214.22.198.51:5060} [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@214.22.198.51:5060} [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@214.22.198.51:5060} [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@214.22.198.51:5060} [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@214.22.198.51:5060} [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, view it on GitHub, or mute the thread.