Hello,
I have some trouble with a remote phone extension connected to a FreePBX through Sangoma SBC.
This setup was used for my scenario:
A phonecall from my cellphone to a remote extension is going through withput any problems, the thing is once I put the call on hold at the remote extension, the following sip traffic happens:
Remote Extension is 54 (Yealink T42G):
54 sends reinvite to SBC
SBC sends trying back to 54
SBC sends renvite to FreePBX
FreePBX processes reinvite normaly
FreePBX sends trying & OK to SBC
Cellphone hears MOH
here comes the problem:
SBC wants to send OK to 54, but fails with an error:
ada52683-d0c3-4052-bdfa-2b6cc6fa2251 2018-07-05 19:25:29.154402 [INFO] sofia_glue.c:6445 SDP negotiation failed! Remote end supports RTP only. Local profile supports SRTP only.
ada52683-d0c3-4052-bdfa-2b6cc6fa2251 2018-07-05 19:25:29.154402 [ERR] sofia_glue.c:9108 Reinvite Codec Error!
ec123b71-9188-4037-9f7c-2b44dcc1f0c4 2018-07-05 19:25:29.154402 [ERR] sofia_thru.c:5893 Failed processing re-invite SDP offer!
ec123b71-9188-4037-9f7c-2b44dcc1f0c4 2018-07-05 19:25:29.154402 [DEBUG] sofia.c:2150 Processing Sofia event:nua_r_invite status:200 phrase:OK nh:0x2f92bc0Instead, SBC sends “488 Not Acceptable Here” to 54
The whole log from receiving of reinvite up until 488:
recv 1145 bytes from tls/[55.66.77.88]:12379 at 19:25:29.126073:
------------------------------------------------------------------------
INVITE sip:[email protected]:15061;transport=tls SIP/2.0
Via: SIP/2.0/TLS 192.168.69.70:12379;branch=z9hG4bK2310894328;rport
From: <sip:[email protected]:12379;transport=TLS>;tag=2729540576
To: "0123456789" <sip:[email protected]>;tag=NKQcaQQg8pNUg
Call-ID: 3e3213bf-fb1b-1236-5f85-000c29b995a9
CSeq: 2 INVITE
Contact: <sip:[email protected]:12379;transport=TLS>
Content-Type: application/sdp
Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE
Max-Forwards: 70
User-Agent: Yealink SIP-T42G 29.83.0.35
Allow-Events: talk,hold,conference,refer,check-sync
Content-Length: 477
v=0
o=- 20047 20048 IN IP4 192.168.69.70
s=SDP data
c=IN IP4 192.168.69.70
t=0 0
m=audio 11940 RTP/SAVP 0 8 18 9 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:9 G722/8000
a=ptime:20
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:MjEzMThlYzggZGIyNTFiZGY2ODJhODY5MmJkNTU2
a=crypto:2 AES_CM_128_HMAC_SHA1_32 inline:MTJhMTdlYWJkZGFkMTAxMmFmZDE0MjFkOGJkZTAy
a=sendonly
------------------------------------------------------------------------
nta: received INVITE sip:[email protected]:15061;transport=tls SIP/2.0 (CSeq 2)
nta: Via check: received=55.66.77.88
nta: INVITE (2) going to existing leg
nua_stack_process_request nh(0x2eec780): Request allow list is: INVITE,ACK,BYE,CANCEL,OPTIONS,MESSAGE,UPDATE,INFO,REGISTER,REFER,NOTIFY,PUBLISH,SUBSCRIBE
nua_stack_process_request nh(0x2eec780): Checking method INVITE in allow list
nua_stack_process_request nh(0x2eec780): Method INVITE is allowed
nua: do_not_add_contact_to_route=0
send 376 bytes to tls/[55.66.77.88]:12379 at 19:25:29.126404:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/TLS 192.168.69.70:12379;branch=z9hG4bK2310894328;rport=12379;received=55.66.77.88
From: <sip:[email protected]:12379;transport=TLS>;tag=2729540576
To: "0123456789" <sip:[email protected]>;tag=NKQcaQQg8pNUg
Call-ID: 3e3213bf-fb1b-1236-5f85-000c29b995a9
CSeq: 2 INVITE
User-Agent: FPBX-13.0.190.7(13.13.1)
Content-Length: 0
------------------------------------------------------------------------
nta: sent 100 Trying for INVITE (2)
nua(0x2eec780): ready call updated: received received offer
ada52683-d0c3-4052-bdfa-2b6cc6fa2251 2018-07-05 19:25:29.114404 [DEBUG] switch_core_session.c:874 Send signal sofia/External/sip:[email protected]:12379 [BREAK]
ada52683-d0c3-4052-bdfa-2b6cc6fa2251 2018-07-05 19:25:29.114404 [DEBUG] switch_core_session.c:874 Send signal sofia/External/sip:[email protected]:12379 [BREAK]
2018-07-05 19:25:29.134385 [DEBUG] sofia.c:1862 Profile:External Sofia event:nua_i_invite status:100 phrase:Trying nh:0x2eec780 sofia_private:0x278e080 magic:0x278e080
2018-07-05 19:25:29.134385 [DEBUG] sofia_thru.c:3728 Checking for events match; thru_event=nua_i_invite event=nua_i_invite
2018-07-05 19:25:29.134385 [DEBUG] sofia_thru.c:4965 sofia_thru:0x2670108 thru-event event:nua_i_invite(nua_i_invite) status:100 phrase:Trying de:0x22fdbb0 nh:0x2eec780 uac_de:0x2f65f70, uas_de:0x2f63a40, uac_nh:0x2eec780, uas_nh:0x2f92bc0
2018-07-05 19:25:29.134385 [DEBUG] sofia_thru.c:2512 No pending challenge with call-id:3e3213bf-fb1b-1236-5f85-000c29b995a9
2018-07-05 19:25:29.134385 [DEBUG] sofia_thru.c:2450 sofia_thru:0x2670108 Replacing uac.de:0x2f65f70 with de:0x22fdbb0
ec123b71-9188-4037-9f7c-2b44dcc1f0c4 2018-07-05 19:25:29.134385 [DEBUG] sofia_thru.c:5155 Waiting for Channel sofia/Internal/[email protected] to be answered.
ec123b71-9188-4037-9f7c-2b44dcc1f0c4 2018-07-05 19:25:29.134385 [DEBUG] sofia_thru.c:5158 Channel sofia/Internal/[email protected] answered
2018-07-05 19:25:29.134385 [DEBUG] sofia_thru.c:5219 Forwarding INVITE to existing thru-invite leg
ada52683-d0c3-4052-bdfa-2b6cc6fa2251 2018-07-05 19:25:29.134385 [DEBUG] sofia.c:2150 Processing Sofia event:nua_i_invite status:100 phrase:Trying nh:0x2eec780
2018-07-05 19:25:29.134385 [DEBUG] sofia.c:1862 Profile:External Sofia event:nua_i_state status:100 phrase:Trying nh:0x2eec780 sofia_private:0x278e080 magic:0x278e080
ada52683-d0c3-4052-bdfa-2b6cc6fa2251 2018-07-05 19:25:29.134385 [DEBUG] sofia.c:2150 Processing Sofia event:nua_i_state status:100 phrase:Trying nh:0x2eec780
ada52683-d0c3-4052-bdfa-2b6cc6fa2251 2018-07-05 19:25:29.134385 [DEBUG] sofia.c:8140 Handling received [100] with r_sdp=0x2e55d39 nh:0x2eec780 OA_status[1,0,0,0]
ada52683-d0c3-4052-bdfa-2b6cc6fa2251 2018-07-05 19:25:29.134385 [DEBUG] sofia.c:8250 Channel sofia/External/sip:[email protected]:12379 entering state [received][100]
ada52683-d0c3-4052-bdfa-2b6cc6fa2251 2018-07-05 19:25:29.134385 [DEBUG] sofia.c:8273 Remote SDP:
v=0
o=- 20047 20048 IN IP4 192.168.69.70
s=SDP data
c=IN IP4 192.168.69.70
t=0 0
m=audio 11940 RTP/SAVP 0 8 18 9 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendonly
a=ptime:20
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:MjEzMThlYzggZGIyNTFiZGY2ODJhODY5MmJkNTU2
a=crypto:2 AES_CM_128_HMAC_SHA1_32 inline:MTJhMTdlYWJkZGFkMTAxMmFmZDE0MjFkOGJkZTAy
ada52683-d0c3-4052-bdfa-2b6cc6fa2251 2018-07-05 19:25:29.134385 [INFO] sofia.c:8658 call state changed: received -> completed
ada52683-d0c3-4052-bdfa-2b6cc6fa2251 2018-07-05 19:25:29.134385 [DEBUG] sofia.c:8667 Processing nua_callstate_completed. r_sdp (0x2e55d39)
ada52683-d0c3-4052-bdfa-2b6cc6fa2251 2018-07-05 19:25:29.134385 [DEBUG] sofia.c:8841 Delayed re-invite SDP offer processing
send 971 bytes to udp/[192.168.97.254]:5060 at 19:25:29.134915:
------------------------------------------------------------------------
INVITE sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.97.250;rport;branch=z9hG4bKKvKtrc04rg06g
Max-Forwards: 70
From: <sip:[email protected]:5060;transport=udp>;tag=3e6vSHjScjX8N
To: "0123456789" <sip:[email protected]>;tag=as20330cd9
Call-ID: [email protected]:5060
CSeq: 125069700 INVITE
Contact: <sip:[email protected]:5060;transport=udp>
User-Agent: NetBorder Session Controller
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: pw-info-package, path, replaces
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 249
X-FS-Support: update_display
v=0
o=nsc 1530831773 1530831775 IN IP4 192.168.97.250
s=nsc
c=IN IP4 192.168.97.250
t=0 0
m=audio 20246 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=sendonly
a=silenceSupp:off - - - -
a=ptime:20
------------------------------------------------------------------------
nta: sent INVITE (125069700) to */192.168.97.254:5060
nua(0x2f92bc0): ready call updated: calling sent offer
ec123b71-9188-4037-9f7c-2b44dcc1f0c4 2018-07-05 19:25:29.134385 [DEBUG] switch_core_session.c:874 Send signal sofia/Internal/[email protected] [BREAK]
recv 561 bytes from udp/[192.168.97.254]:5060 at 19:25:29.135659:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.97.250;branch=z9hG4bKKvKtrc04rg06g;received=192.168.97.250;rport=5060
From: <sip:[email protected]:5060;transport=udp>;tag=3e6vSHjScjX8N
To: "0123456789" <sip:[email protected]>;tag=as20330cd9
Call-ID: [email protected]:5060
CSeq: 125069700 INVITE
Server: FPBX-13.0.190.7(13.13.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: <sip:[email protected]:5060>
Content-Length: 0
------------------------------------------------------------------------
nta: received 100 Trying for INVITE (125069700)
nta: 100 Trying is going to a transaction
recv 924 bytes from udp/[192.168.97.254]:5060 at 19:25:29.135885:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.97.250;branch=z9hG4bKKvKtrc04rg06g;received=192.168.97.250;rport=5060
From: <sip:[email protected]:5060;transport=udp>;tag=3e6vSHjScjX8N
To: "0123456789" <sip:[email protected]>;tag=as20330cd9
Call-ID: [email protected]:5060
CSeq: 125069700 INVITE
Server: FPBX-13.0.190.7(13.13.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: <sip:[email protected]:5060>
Content-Type: application/sdp
Content-Length: 334
v=0
o=root 1453308004 1453308005 IN IP4 192.168.97.254
s=Asterisk PBX 13.13.1
c=IN IP4 192.168.97.254
t=0 0
m=audio 19936 RTP/AVP 0 8 3 111 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:111 G726-32/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=recvonly
------------------------------------------------------------------------
nta: received 200 OK for INVITE (125069700)
nta: 200 OK is going to a transaction
nua(0x2f92bc0): INVITE: processed SDP answer in 200 OK
nua(0x2f92bc0): ready call updated: completing received answer
ec123b71-9188-4037-9f7c-2b44dcc1f0c4 2018-07-05 19:25:29.134385 [DEBUG] switch_core_session.c:874 Send signal sofia/Internal/[email protected] [BREAK]
ec123b71-9188-4037-9f7c-2b44dcc1f0c4 2018-07-05 19:25:29.134385 [DEBUG] switch_core_session.c:874 Send signal sofia/Internal/[email protected] [BREAK]
2018-07-05 19:25:29.154402 [DEBUG] sofia.c:1862 Profile:Internal Sofia event:nua_i_state status:0 phrase:INVITE sent nh:0x2f92bc0 sofia_private:0x2d9a080 magic:0x2d9a080
ec123b71-9188-4037-9f7c-2b44dcc1f0c4 2018-07-05 19:25:29.154402 [DEBUG] sofia.c:2150 Processing Sofia event:nua_i_state status:0 phrase:INVITE sent nh:0x2f92bc0
ec123b71-9188-4037-9f7c-2b44dcc1f0c4 2018-07-05 19:25:29.154402 [DEBUG] sofia.c:8140 Handling calling [0] with r_sdp=(nil) nh:0x2f92bc0 OA_status[0,0,1,0]
ec123b71-9188-4037-9f7c-2b44dcc1f0c4 2018-07-05 19:25:29.154402 [DEBUG] sofia.c:8250 Channel sofia/Internal/[email protected] entering state [calling][0]
2018-07-05 19:25:29.154402 [DEBUG] sofia.c:1862 Profile:Internal Sofia event:nua_r_invite status:200 phrase:OK nh:0x2f92bc0 sofia_private:0x2d9a080 magic:0x2d9a080
2018-07-05 19:25:29.154402 [DEBUG] sofia_thru.c:3728 Checking for events match; thru_event=nua_i_invite event=nua_r_invite
2018-07-05 19:25:29.154402 [DEBUG] sofia_thru.c:4965 sofia_thru:0x2670108 thru-event event:nua_r_invite(nua_i_invite) status:200 phrase:OK de:0x2f63ae0 nh:0x2f92bc0 uac_de:0x22fdbb0, uas_de:0x2f63a40, uac_nh:0x2eec780, uas_nh:0x2f92bc0
2018-07-05 19:25:29.154402 [DEBUG] sofia_thru.c:2474 sofia_thru:0x2670108 Replacing uas.de:0x2f63a40 with de:0x2f63ae0
2018-07-05 19:25:29.154402 [DEBUG] sofia_thru.c:5785 Sending thru-response back to original leg (nua_r_invite)
2018-07-05 19:25:29.154402 [DEBUG] sofia_thru.c:5833 Forwarding thru response to session ada52683-d0c3-4052-bdfa-2b6cc6fa2251 (nh=0x2eec780)
ec123b71-9188-4037-9f7c-2b44dcc1f0c4 2018-07-05 19:25:29.154402 [DEBUG] sofia_glue.c:9014 Waiting for peer channel[sofia/Internal/[email protected]] to be answered before processing reinvite sdp offer
ec123b71-9188-4037-9f7c-2b44dcc1f0c4 2018-07-05 19:25:29.154402 [DEBUG] sofia_glue.c:9019 Channel[sofia/Internal/[email protected]] answered
ada52683-d0c3-4052-bdfa-2b6cc6fa2251 2018-07-05 19:25:29.154402 [DEBUG] sofia_glue.c:9033 Processing reinvite sdp offer r_sdp[0x2a181c0]=
v=0
o=- 20047 20048 IN IP4 192.168.69.70
s=SDP data
c=IN IP4 192.168.69.70
t=0 0
m=audio 11940 RTP/SAVP 0 8 18 9 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendonly
a=ptime:20
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:MjEzMThlYzggZGIyNTFiZGY2ODJhODY5MmJkNTU2
a=crypto:2 AES_CM_128_HMAC_SHA1_32 inline:MTJhMTdlYWJkZGFkMTAxMmFmZDE0MjFkOGJkZTAy
ada52683-d0c3-4052-bdfa-2b6cc6fa2251 2018-07-05 19:25:29.154402 [DEBUG] sofia_glue.c:5515 Performing SDP negotiation
ada52683-d0c3-4052-bdfa-2b6cc6fa2251 2018-07-05 19:25:29.154402 [DEBUG] switch_channel.c:1535 (sofia/External/sip:[email protected]:12379) Callstate Change ACTIVE -> HELD
ada52683-d0c3-4052-bdfa-2b6cc6fa2251 2018-07-05 19:25:29.154402 [DEBUG] sofia_glue.c:5871 Found first active audio media line
ada52683-d0c3-4052-bdfa-2b6cc6fa2251 2018-07-05 19:25:29.154402 [DEBUG] sofia_glue.c:5923 Existing key is still valid.
ada52683-d0c3-4052-bdfa-2b6cc6fa2251 2018-07-05 19:25:29.154402 [DEBUG] sofia_glue.c:3650 Set Local Key [2 AES_CM_128_HMAC_SHA1_32 inline:ieiClMqRLP61Lrxf/tddVd5gLqWCx5qzxW8i/A7K]
ada52683-d0c3-4052-bdfa-2b6cc6fa2251 2018-07-05 19:25:29.154402 [DEBUG] sofia_glue.c:5978 Ignoring unacceptable key
ada52683-d0c3-4052-bdfa-2b6cc6fa2251 2018-07-05 19:25:29.154402 [DEBUG] sofia_glue.c:6140 First codec 0, last codec 5, total number of codecs 5
ada52683-d0c3-4052-bdfa-2b6cc6fa2251 2018-07-05 19:25:29.154402 [DEBUG] sofia_glue.c:6151 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000]
ada52683-d0c3-4052-bdfa-2b6cc6fa2251 2018-07-05 19:25:29.154402 [DEBUG] sofia_glue.c:3523 Already using PCMU
2018-07-05 19:25:29.154402 [DEBUG] switch_core_sqldb.c:1520 Secure Type: srtp:AES_CM_128_HMAC_SHA1_32
ada52683-d0c3-4052-bdfa-2b6cc6fa2251 2018-07-05 19:25:29.154402 [DEBUG] sofia_glue.c:6278 Set 2833 dtmf send payload to 101
ada52683-d0c3-4052-bdfa-2b6cc6fa2251 2018-07-05 19:25:29.154402 [INFO] sofia_glue.c:6445 SDP negotiation failed! Remote end supports RTP only. Local profile supports SRTP only.
ada52683-d0c3-4052-bdfa-2b6cc6fa2251 2018-07-05 19:25:29.154402 [ERR] sofia_glue.c:9108 Reinvite Codec Error!
ec123b71-9188-4037-9f7c-2b44dcc1f0c4 2018-07-05 19:25:29.154402 [ERR] sofia_thru.c:5893 Failed processing re-invite SDP offer!
ec123b71-9188-4037-9f7c-2b44dcc1f0c4 2018-07-05 19:25:29.154402 [DEBUG] sofia.c:2150 Processing Sofia event:nua_r_invite status:200 phrase:OK nh:0x2f92bc0
send 639 bytes to tls/[55.66.77.88]:12379 at 19:25:29.155117:
------------------------------------------------------------------------
SIP/2.0 488 Not Acceptable Here
Via: SIP/2.0/TLS 192.168.69.70:12379;branch=z9hG4bK2310894328;rport=12379;received=55.66.77.88
From: <sip:[email protected]:12379;transport=TLS>;tag=2729540576
To: "0123456789" <sip:[email protected]>;tag=NKQcaQQg8pNUg
Call-ID: 3e3213bf-fb1b-1236-5f85-000c29b995a9
CSeq: 2 INVITE
User-Agent: FPBX-13.0.190.7(13.13.1)
Accept: application/csta+v6+json, application/csta+json, application/csta+xml, application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: pw-info-package, path, replaces
Content-Length: 0
------------------------------------------------------------------------11.22.33.44 sbc public IP
55.66.77.88 remote extension 54 public IP
192.168.69.70 remote extension 54 local IP
192.168.97.254 freepbx local IP
192.168.97.250 sbc local ip
0123456789 cellphone number
Besides that, calls are working in both ways.
Is there a way to get more information out of the SBC why it suddenly thinks the remote extension would only support RTP instead of SRTP?
SBC Version 2.3.19-102 (GA)
FreePBX Version 13.0.190.7
FreePBX Asterisk Version 13.13.1
Yealink Firmware 29.83.0.35
Regards,
Xeoniz