Hi All,
Sorry for the trouble. issue was beyond opensips. the forwarding asterisk
server forks the call to both opensips and to another endpoint, the second
endpoint answers the call hence asterisk sends a CANCEL to opensips to cancel
the ongoing transaction towards teams which makes sense now, Everything working
as expected.
Thank you.
Distinguishing What && How !
On Thursday, 2 September 2021, 06:40:16 pm GMT+5:30, Pasan Meemaduma
<[email protected]> wrote:
Hi Guys,
upon further checking I'm seeing opensips sending a CANCEL as while microsoft
teams replying with a 100 Trying. Is this I'm missing something for
multi-tenancy in opensips config? I can even see a 180 Ringing coming but it
appears opensips cancelling the transaction right after it send the INVITE to
teams. Following is my opensips.cfg for aliases. I tried adding the second
domain as an alias too, but it has no effect.
Thank you
/etc/opensips.cfg
auto_aliases=no
alias=tls:voippabx.cloud:5061
alias=tls:pasanm.voippabx.cloud:5061
alias=udp:172.31.36.39:5060
listen=tls:172.31.36.39:5061
listen=udp:172.31.36.39:5060 # CUSTOMIZE ME
advertised_address=x.x.x.x
#### Transaction Module
loadmodule "tm.so"
modparam("tm", "fr_timeout", 15)
modparam("tm", "fr_inv_timeout", 90)
modparam("tm", "restart_fr_on_each_reply", 0)
modparam("tm", "onreply_avp_mode", 1)
modparam("tm", "via1_matching", 0)
modparam("tm", "ruri_matching", 0)
modparam("tls_mgm", "certificate", "/etc/opensips/tls/default.crt")
modparam("tls_mgm", "private_key","/etc/opensips/tls/default.key")
modparam("tls_mgm", "ca_list", "/etc/opensips/tls/ca-default.crt")
modparam("tls_mgm", "ca_dir", "/etc/ssl/certs/")
modparam("tls_mgm","verify_cert", "1")
modparam("tls_mgm","require_cert", "1")
modparam("tls_mgm", "server_domain", "dom1=172.31.36.39:5061")
modparam("tls_mgm","verify_cert", "[dom1]0")
modparam("tls_mgm","require_cert", "[dom1]1")
modparam("tls_mgm","tls_method", "[dom1]TLSv1_2")
modparam("tls_mgm","certificate",
"[dom1]/etc/tls/voippabx.cloud/voippabx.cloud.crt")
modparam("tls_mgm","private_key",
"[dom1]/etc/tls/voippabx.cloud/voippabx.cloud.key")
modparam("tls_mgm", "ca_list",
"[dom1]/etc/tls/voippabx.cloud/voippabx.cloud-ca.crt")
modparam("tls_mgm", "ca_dir", "[dom1]/etc/ssl/certs/")
modparam("tls_mgm", "tls_handshake_timeout", 3000)
modparam("proto_tls", "tls_max_msg_chunks", 4048)
--- fail call log of inbound call to teams ---
[29809] DBG:proto_tls:tls_update_fd: New fd is 73
[29809] DBG:proto_tls:tls_write: write was successful (1240 bytes)
[29809] DBG:proto_tls:proto_tls_send: after write: c= 0x7fa175ec28e8 n=1240
fd=73
[29809] DBG:proto_tls:proto_tls_send: buf=
INVITE sip:[email protected] SIP/2.0
Record-Route:
<sip:pasanm.voippabx.cloud:5061;transport=tls;ftag=as0e54f44e;lr;r2=on>
Record-Route: <sip:172.31.36.39:5060;ftag=as0e54f44e;lr;r2=on>
Via: SIP/2.0/TLS a.a.a.a:5061;branch=z9hG4bKa8.655a009.0;i=0599f386
Via: SIP/2.0/TLS
b.b.b.b:5061;received=b.b.b.b;branch=z9hG4bK4449b234;rport=34212
Max-Forwards: 69
From: "Private" <sip:[email protected]>;tag=as0e54f44e
To: <sip:[email protected]>
Contact: <sip:[email protected]:5061;transport=tls>
Call-ID: [email protected]:5061
CSeq: 102 INVITE
User-Agent: Asterisk PBX 16.2.1~dfsg-1+deb10u2
Date: Thu, 02 Sep 2021 11:14:53 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces
Content-Type: application/sdp
Content-Length: 339
#015
v=0
o=root 698222221 698222221 IN IP4 b.b.b.b
s=Asterisk PBX 16.2.1~dfsg-1+deb10u2
c=IN IP4 b.b.b.b
t=0 0
m=audio 11364 RTP/SAVP 8 101
a=crypto:1 AES_CM_128_HMAC_SHA1_80
inline:EQ71mHmln2YJHJn8ujv0J/v+MiH6XJlfv7lSiXsv
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=maxptime:150
a=sendrecv
[29809] DBG:tm:insert_timer_unsafe: [0]: 0x7fa175f4c480 (939)
[29809] DBG:tm:do_t_cleanup: transaction 0x7fa175f4c230 already updated!
Skipping update!
[29809] DBG:tm:t_unref: UNREF_UNSAFE: [0x7fa175f4c230] after is 0
[29809] DBG:core:destroy_avp_list: destroying list (nil)
[29809] DBG:core:receive_msg: cleaning up
[29809] DBG:proto_tls:tls_read_req: tls_read_req end
[29809] DBG:proto_tls:tls_read_req: Using the global ( per process ) buff
[29809] DBG:proto_tls:tls_update_fd: New fd is 5
[29809] DBG:proto_tls:_tls_read: 460 bytes read
[29809] DBG:proto_tls:tcp_handle_req: content-length= 0
[29809] DBG:proto_tls:tcp_handle_req: Nothing more to read on TCP conn
0x7fa175ea5000, currently in state 0
[29809] DBG:core:parse_msg: SIP Request:
[29809] DBG:core:parse_msg: method: <CANCEL>
[29809] DBG:core:parse_msg: uri:
<sip:[email protected]>
[29809] DBG:core:parse_msg: version: <SIP/2.0>
[29809] DBG:core:parse_headers: flags=ffffffffffffffff
[29809] DBG:core:parse_via_param: found param type 232, <branch> =
<z9hG4bK4449b234>; state=6
[29809] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>;
state=17
[29809] DBG:core:parse_via: end of header reached, state=5
[29809] DBG:core:parse_headers: via found, flags=ffffffffffffffff
[29809] DBG:core:parse_headers: this is the first via
[29809] DBG:core:_parse_to: end of header reached, state=10
[29809] DBG:core:_parse_to: display={},
ruri={sip:[email protected]}
[29809] DBG:core:get_hdr_field: <To> [46];
uri=[sip:[email protected]]
[29809] DBG:core:get_hdr_field: to body
[<sip:[email protected]>
]
[29809] DBG:core:get_hdr_field: cseq <CSeq>: <102> <CANCEL>
[29809] DBG:core:get_hdr_field: content_length=0
[29809] DBG:core:get_hdr_field: found end of header
[29809] DBG:core:receive_msg: After parse_msg...
[29809] DBG:core:receive_msg: preparing to run routing scripts...
[29809] DBG:maxfwd:is_maxfwd_present: value = 70
[29809] DBG:core:parse_headers: flags=78
[29809] DBG:tm:t_lookupOriginalT: searching on hash entry 138
[29809] DBG:tm:matching_3261: RFC3261 transaction matched, tid=4449b234
[29809] DBG:tm:t_lookupOriginalT: canceled transaction found
(0x7fa175f4c230)!
[29809] DBG:tm:t_lookupOriginalT: REF_UNSAFE:[0x7fa175f4c230] after is 1
[29809] DBG:tm:t_lookupOriginalT: t_lookupOriginalT completed
[29809] DBG:uri:has_totag: no totag
[29809] DBG:core:parse_headers: flags=78
[29809] DBG:tm:t_newtran: transaction on entrance=0xffffffffffffffff
[29809] DBG:core:parse_headers: flags=ffffffffffffffff
[29809] DBG:core:parse_headers: flags=78
[29809] DBG:tm:t_lookup_request: start searching: hash=138, isACK=0
[29809] DBG:tm:matching_3261: RFC3261 transaction matching failed
[29809] DBG:tm:t_lookup_request: no transaction found
[29809] DBG:core:MD5StringArray: MD5 calculated:
691657b3333bfaff8b58f9a39aceccad
[29809] DBG:core:parse_headers: flags=ffffffffffffffff
[29809] DBG:core:_shm_resize: resize(0) called
[29809] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
[29809] DBG:tm:insert_timer_unsafe: [2]: 0x7fa175f6d250 (929)
[29809] DBG:core:tcp_conn_get: con found in state 0
[29809] DBG:core:tcp_conn_get: tcp connection found (0x7fa175ea5000) already
in this process ( 14 ) , fd = 5
[29809] DBG:proto_tls:proto_tls_send: sending via fd 5...
[29809] DBG:proto_tls:tls_update_fd: New fd is 5
[29809] DBG:proto_tls:tls_write: write was successful (415 bytes)
[29809] DBG:proto_tls:proto_tls_send: after write: c= 0x7fa175ea5000 n=415
fd=5
[29809] DBG:proto_tls:proto_tls_send: buf=
SIP/2.0 200 canceling
Via: SIP/2.0/TLS
b.b.b.b:5061;received=b.b.b.b;branch=z9hG4bK4449b234;rport=34212
From: "Private" <sip:[email protected]>;tag=as0e54f44e
To:
<sip:[email protected]>;tag=b731-691657b3333bfaff8b58f9a39aceccad
Call-ID: [email protected]:5061
CSeq: 102 CANCEL
Server: OpenSIPS (2.4.8 (x86_64/linux))
Content-Length: 0
#015
[29809] DBG:tm:_reply_light: reply sent out. buf=0x7fa17de3dfa0: SIP/2.0
2..., shmem=0x7fa175f07700: SIP/2.0 2
[29811] DBG:core:parse_msg: SIP Reply (status):
[29811] DBG:core:parse_msg: version: <SIP/2.0>
[29811] DBG:core:parse_msg: status: <100>
[29811] DBG:core:parse_msg: reason: <Trying>
[29811] DBG:core:parse_headers: flags=ffffffffffffffff
[29811] DBG:core:_parse_to: end of header reached, state=10
[29811] DBG:core:_parse_to: display={},
ruri={sip:[email protected]}
[29811] DBG:core:get_hdr_field: <TO> [46];
uri=[sip:[email protected]]
[29811] DBG:core:get_hdr_field: to body
[<sip:[email protected]>
]
[29811] DBG:core:get_hdr_field: cseq <CSEQ>: <102> <INVITE>
[29811] DBG:core:parse_via_param: found param type 232, <branch> =
<z9hG4bKa8.655a009.0>; state=6
[29811] DBG:core:parse_via_param: found param type 236, <i> = <0599f386>;
state=9
[29811] DBG:core:parse_via: next_via
[29811] DBG:core:parse_via_param: found param type 234, <received> =
<b.b.b.b>; state=6
[29811] DBG:core:parse_via_param: found param type 232, <branch> =
<z9hG4bK4449b234>; state=6
[29811] DBG:core:parse_via_param: found param type 235, <rport> = <34212>;
state=16
[29811] DBG:core:parse_via: end of header reached, state=5
[29811] DBG:core:parse_headers: via found, flags=ffffffffffffffff
[29811] DBG:core:parse_headers: this is the first via
[29811] DBG:core:get_hdr_field: content_length=0
[29811] DBG:core:get_hdr_field: found end of header
[29811] DBG:core:receive_msg: After parse_msg...
[29811] DBG:core:forward_reply: found module tm, passing reply to it
[29811] DBG:tm:t_check: start=0xffffffffffffffff
[29811] DBG:core:parse_headers: flags=22
[29811] DBG:core:parse_headers: flags=8
[29811] DBG:tm:t_reply_matching: hash 138 label 151037270 branch 0
[29811] DBG:tm:t_reply_matching: REF_UNSAFE:[0x7fa175f4c230] after is 1
[29811] DBG:tm:t_reply_matching: reply matched (T=0x7fa175f4c230)!
[29811] DBG:tm:t_check: end=0x7fa175f4c230
[29811] DBG:tm:reply_received: org. status uas=100, uac[0]=0 local=0
is_invite=1)
[29811] incoming reply: RR=Trying, RS=100, SI=52.114.16.74
[email protected]:5061
[29811] DBG:tm:build_local: using FROM=<From: "Private"
<sip:[email protected]>;tag=as0e54f44e
>, TO=<To: <sip:[email protected]>
>, CSEQ_N=<CSeq: 102>
[29811] DBG:tm:cancel_branch: sending cancel...
[29811] DBG:core:tcp_conn_get: con found in state 0
[29811] DBG:core:tcp_conn_get: tcp connection found (0x7fa175ec28e8) already
in this process ( 16 ) , fd = 5
[29811] DBG:proto_tls:proto_tls_send: sending via fd 5...
[29811] DBG:proto_tls:tls_update_fd: New fd is 5
[29811] DBG:proto_tls:tls_write: write was successful (398 bytes)
[29811] DBG:proto_tls:proto_tls_send: after write: c= 0x7fa175ec28e8 n=398
fd=5
[29811] DBG:proto_tls:proto_tls_send: buf=
CANCEL sip:[email protected] SIP/2.0
Via: SIP/2.0/TLS a.a.a.a:5061;branch=z9hG4bKa8.655a009.0
From: "Private" <sip:[email protected]>;tag=as0e54f44e
Call-ID: [email protected]:5061
To: <sip:[email protected]>
CSeq: 102 CANCEL
Max-Forwards: 70
User-Agent: OpenSIPS (2.4.8 (x86_64/linux))
Content-Length: 0
#015
[29811] DBG:tm:insert_timer_unsafe: [0]: 0x7fa175f4c548 (939)
[29811] DBG:tm:t_should_relay_response: T_code=100, new_code=100
[29811] DBG:tm:relay_reply: T_state=5, branch=0, save=0, relay=-1,
cancel_BM=0
[29811] DBG:tm:reply_received: FR_INV_TIMER = 90
[29811] DBG:tm:set_timer: relative timeout is 90
[29811] DBG:tm:insert_timer_unsafe: [1]: 0x7fa175f4c480 (1014)
SIP/2.0 180 Ringing
FROM: "Private"<sip:[email protected]>;tag=as5d689a00
TO:
<sip:[email protected]>;tag=e4748eaef0f44bf687956fe76d968596
CSEQ: 102 INVITE
CALL-ID: [email protected]:5061
VIA: SIP/2.0/TLS
b.b.b.b:5061;received=b.b.b.b;branch=z9hG4bK502b3c25;rport=34212
RECORD-ROUTE:
<sip:sip-du-a-au.pstnhub.microsoft.com:5061;transport=tls;lr>,<sip:pasanm.voippabx.cloud:5061;transport=tls;ftag=as5d689a00;lr;r2=on>,<sip:172.31.36.39:5060;ftag=as5d689a00;lr;r2=on>
CONTACT:
<sip:api-du-a-auea.pstnhub.microsoft.com:443;x-i=f65bd2eb-86c9-4a76-85ea-84f5df8f4635;x-c=595513d129e95e99bf4e9e900b804fe1/s/1/e4f1e971d27f46829c743e805ba58c16>
CONTENT-LENGTH: 0
ALLOW: INVITE,ACK,OPTIONS,CANCEL,BYE,NOTIFY
SERVER: Microsoft.PSTNHub.SIPProxy v.2021.8.30.8 i.AUEA.2
#015
DBG:tm:relay_reply: sent buf=0x7fa17de3e820: SIP/2.0 1...,
shmem=0x7fa175f768a8: SIP/2.0 1
DBG:tm:reply_received: FR_INV_TIMER = 90
DBG:tm:set_timer: relative timeout is 90
DBG:tm:insert_timer_unsafe: [1]: 0x7fa175f4c480 (1721)
DBG:tm:t_unref: UNREF_UNSAFE: [0x7fa175f4c230] after is 0
DBG:core:destroy_avp_list: destroying list (nil)
DBG:core:receive_msg: cleaning up
DBG:proto_tls:tls_read_req: tls_read_req end
DBG:proto_tls:tls_read_req: Using the global ( per process ) buff
DBG:proto_tls:tls_update_fd: New fd is 5
DBG:proto_tls:_tls_read: 460 bytes read
DBG:proto_tls:tcp_handle_req: content-length= 0
DBG:proto_tls:tcp_handle_req: Nothing more to read on TCP conn 0x7fa175ea5000,
currently in state 0
DBG:core:parse_msg: SIP Request:
DBG:core:parse_msg: method: <CANCEL>
DBG:core:parse_msg: uri: <sip:[email protected]>
DBG:core:parse_msg: version: <SIP/2.0>
DBG:core:parse_headers: flags=ffffffffffffffff
DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK502b3c25>;
state=6
DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17
DBG:core:parse_via: end of header reached, state=5
DBG:core:parse_headers: via found, flags=ffffffffffffffff
DBG:core:parse_headers: this is the first via
DBG:core:_parse_to: end of header reached, state=10
DBG:core:_parse_to: display={},
ruri={sip:[email protected]}
DBG:core:get_hdr_field: <To> [46];
uri=[sip:[email protected]]
DBG:core:get_hdr_field: to body [<sip:[email protected]>
]
DBG:core:get_hdr_field: cseq <CSeq>: <102> <CANCEL>
DBG:core:get_hdr_field: content_length=0
DBG:core:get_hdr_field: found end of header
DBG:core:receive_msg: After parse_msg...
DBG:core:receive_msg: preparing to run routing scripts...
DBG:maxfwd:is_maxfwd_present: value = 70
DBG:core:parse_headers: flags=78
DBG:tm:t_lookupOriginalT: searching on hash entry 19441
DBG:tm:matching_3261: RFC3261 transaction matched, tid=502b3c25
DBG:tm:t_lookupOriginalT: canceled transaction found (0x7fa175f4c230)!
DBG:tm:t_lookupOriginalT: REF_UNSAFE:[0x7fa175f4c230] after is 1
DBG:tm:t_lookupOriginalT: t_lookupOriginalT completed
DBG:uri:has_totag: no totag
DBG:core:parse_headers: flags=78
DBG:tm:t_newtran: transaction on entrance=0xffffffffffffffff
DBG:core:parse_headers: flags=ffffffffffffffff
DBG:core:parse_headers: flags=78
DBG:tm:t_lookup_request: start searching: hash=19441, isACK=0
DBG:tm:matching_3261: RFC3261 transaction matching failed
DBG:tm:t_lookup_request: no transaction found
DBG:core:MD5StringArray: MD5 calculated: 31453c5e285c477e8c5ea130fd29f816
DBG:core:parse_headers: flags=ffffffffffffffff
DBG:core:_shm_resize: resize(0) called
DBG:tm:cleanup_uac_timers: RETR/FR timers reset
DBG:tm:insert_timer_unsafe: [2]: 0x7fa175f6d250 (1636)
DBG:core:tcp_conn_get: con found in state 0
DBG:core:tcp_conn_get: tcp connection found (0x7fa175ea5000) already in this
process ( 14 ) , fd = 5
DBG:proto_tls:proto_tls_send: sending via fd 5...
DBG:proto_tls:tls_update_fd: New fd is 5
DBG:proto_tls:tls_write: write was successful (415 bytes)
DBG:proto_tls:proto_tls_send: after write: c= 0x7fa175ea5000 n=415 fd=5
DBG:proto_tls:proto_tls_send: buf=
SIP/2.0 200 canceling
Via: SIP/2.0/TLS
b.b.b.b:5061;received=b.b.b.b;branch=z9hG4bK502b3c25;rport=34212
From: "Private" <sip:[email protected]>;tag=as5d689a00
To:
<sip:[email protected]>;tag=b731-31453c5e285c477e8c5ea130fd29f816
Call-ID: [email protected]:5061
CSeq: 102 CANCEL
Server: OpenSIPS (2.4.8 (x86_64/linux))
Content-Length: 0
#015
Distinguishing What && How !
On Wednesday, 1 September 2021, 03:07:59 pm GMT+5:30, Pasan Meemaduma via
Users <[email protected]> wrote:
Hi All,
I hope all of you are well and safe. I was able to setup teams direct routing
referring to this blogpost
https://blog.opensips.org/2019/09/16/opensips-as-ms-teams-sbc/
When I add a second tenant, incoming calls to the second tenant don't work, as
Microsoft teams not responding to the invite. outgoing calls from the second
tenant works fine.
I have configured the second tenant using a derived trunk. any idea why
following INVITE not respond by Microsoft but later (first tenant INVITE )
works?
------ SECOND TENANT INVITE -------
Sep 1 17:13:47 msteams-sbc opensips[26043]: INVITE
sip:[email protected] SIP/2.0
Sep 1 17:13:47 msteams-sbc opensips[26043]: Record-Route:
<sip:pasanm.voippabx.cloud:5061;transport=tls;ftag=as0e9dc8dc;lr;r2=on>
Sep 1 17:13:47 msteams-sbc opensips[26043]: Record-Route:
<sip:172.31.36.39:5060;ftag=as0e9dc8dc;lr;r2=on>
Sep 1 17:13:47 msteams-sbc opensips[26043]: Via: SIP/2.0/TLS
x.x.x.x:5061;branch=z9hG4bKf0c.bd20fe7.0;i=609325e7
Sep 1 17:13:47 msteams-sbc opensips[26043]: Via: SIP/2.0/TLS
y.y.y.y:5061;received=y.y.y.y;branch=z9hG4bK54c25df9;rport=49408
Sep 1 17:13:47 msteams-sbc opensips[26043]: Max-Forwards: 69
Sep 1 17:13:47 msteams-sbc opensips[26043]: From: "Private"
<sip:[email protected]>;tag=as0e9dc8dc
Sep 1 17:13:47 msteams-sbc opensips[26043]: To:
<sip:[email protected]>
Sep 1 17:13:47 msteams-sbc opensips[26043]: Contact:
<sip:[email protected]:5061;transport=tls>
---FIRST TENANT INVITE---- (WORKING)
Sep 1 17:17:46 msteams-sbc opensips[26043]: INVITE
sip:[email protected] SIP/2.0
Sep 1 17:17:46 msteams-sbc opensips[26043]: Record-Route:
<sip:voippabx.cloud:5061;transport=tls;ftag=as5e20130f;lr;r2=on>
Sep 1 17:17:46 msteams-sbc opensips[26043]: Record-Route:
<sip:172.31.36.39:5060;ftag=as5e20130f;lr;r2=on>
Sep 1 17:17:46 msteams-sbc opensips[26043]: Via: SIP/2.0/TLS
x.x.x.x:5061;branch=z9hG4bKe5f8.239f87a3.0;i=009325e7
Sep 1 17:17:46 msteams-sbc opensips[26043]: Via: SIP/2.0/TLS
z.z.z.z:5061;received=z.z.z.z;branch=z9hG4bK7ff0149e;rport=44650
Sep 1 17:17:46 msteams-sbc opensips[26043]: Max-Forwards: 69
Sep 1 17:17:46 msteams-sbc opensips[26043]: From: "Extension"
<sip:[email protected]>;tag=as5e20130f
Sep 1 17:17:46 msteams-sbc opensips[26043]: To:
<sip:[email protected]>
Sep 1 17:17:46 msteams-sbc opensips[26043]: Contact:
<sip:[email protected]:5061;transport=tls>
I only have voippabx.cloud configured as a sbc on first Tenant. As per the
above documentation I'm putting correct domain on RR header. Did I miss
anything? Thank you.
Distinguishing What && How
!_______________________________________________
Users mailing list
[email protected]
http://lists.opensips.org/cgi-bin/mailman/listinfo/users
_______________________________________________
Users mailing list
[email protected]
http://lists.opensips.org/cgi-bin/mailman/listinfo/users
