Hi,
I have FreeSWITCH server with two softphones and one Polycom VVX 310 phone. All endpoints use SRTP.
One softphone and Polycom phone are registered as same user. When I make a call to that user, softphone and Polycom both ring as expected.
Problem is that Polycom does early media, so it sends encryption key in 183 message and FreeSWITCH does not update key if I answer on softphone and call breaks after several "SRTP audio unprotect failed with code 7 (auth check failed) 83 bytes 10 errors" errors.
Does anyone know of any solution for that?
Call to Polycom
----------------------------------------------------
------------------------------------------------------------------------
recv 1268 bytes from udp/[XXX.XXX.XXX.XXX]:5060 at 13:23:24.192990:
------------------------------------------------------------------------
SIP/2.0 183 Session Progress
P-Asserted-Identity: "User Name" <sip:User.Name@domain.tld>,<tel:+11111111111;ext=1111>
Via: SIP/2.0/UDP XXX.XXX.XXX.XXX:5062;received=XXX.XXX.XXX.XXX;rport=5062;branch=z9hG4bKH13aN0H9550Ue
From: "Extension 1000" <sip:1000@fs01.domain.tld>;tag=vvZQ9m8H03Npp
To: "User Name" <sip:User.Name@domain.tld>;epid=0004f2853296;tag=BB7B7F4F-B75734BA
CSeq: 737508 INVITE
Call-ID: 5eaff2fd-aeec-1237-6aaa-00155d018038
Contact: <sip:User.Name@domain.tld;opaque=user:epid:eji6PlZNF1Sy2o_kLXZ3sQAA;gruu>
Record-Route: <sip:ucs.domain.tld:5061;transport=tls;ms-fe=server3.domain.tld;opaque=state:T;lr>, <sip:XXX.XXX.XXX.XXX:5061;transport=tls;r2=on;lr>, <sip:XXX.XXX.XXX.XXX;r2=on;lr>
User-Agent: Polycom/5.9.0.9373 PolycomVVX-VVX_310-UA/5.9.0.9373
Accept-Language: en
Content-Type: application/sdp
Content-Length: 354
v=0
o=- 1550582604 1550582604 IN IP4 YYY.YYY.YYY.YYY
s=Polycom IP Phone
c=IN IP4 YYY.YYY.YYY.YYY
t=0 0
a=sendrecv
m=audio 5380 RTP/SAVP 102 101
a=crypto:5 AES_CM_128_HMAC_SHA1_80 inline:GKS3Pyolq2FNrLsVljrZWO3ziKdaRG+9G8mXDn2F|2^31|1:1
a=rtpmap:102 G7221/16000
a=fmtp:102 bitrate=24000
a=rtpmap:101 telephone-event/8000
a=sendrecv
a=rtcp:5381
------------------------------------------------------------------------
2019-02-19 13:23:23.731999 [INFO] sofia.c:1356 sofia/internal/User.Name(a)domain.tld Update Callee ID to "User Name" <User.Name>
2019-02-19 13:23:23.731999 [DEBUG] sofia.c:7291 Channel sofia/internal/User.Name(a)domain.tld entering state [proceeding][183]
2019-02-19 13:23:23.731999 [DEBUG] sofia.c:7301 Remote SDP:
v=0
o=- 1550582604 1550582604 IN IP4 YYY.YYY.YYY.YYY
s=Polycom IP Phone
c=IN IP4 YYY.YYY.YYY.YYY
t=0 0
a=sendrecv
m=audio 5380 RTP/SAVP 102 101
a=rtpmap:102 G7221/16000
a=fmtp:102 bitrate=24000
a=rtpmap:101 telephone-event/8000
a=crypto:5 AES_CM_128_HMAC_SHA1_80 inline:GKS3Pyolq2FNrLsVljrZWO3ziKdaRG+9G8mXDn2F|2^31|1:1
a=rtcp:5381
2019-02-19 13:23:23.731999 [NOTICE] sofia.c:7304 Pre-Answer sofia/internal/User.Name(a)domain.tld!
2019-02-19 13:23:23.731999 [DEBUG] switch_channel.c:3482 (sofia/internal/User.Name(a)domain.tld) Callstate Change RINGING -> EARLY
2019-02-19 13:23:23.731999 [DEBUG] switch_core_media.c:1804 looking for crypto suite [AEAD_AES_256_GCM_8]alias=[] in [5 AES_CM_128_HMAC_SHA1_80 inline:GKS3Pyolq2FNrLsVljrZWO3ziKdaRG+9G8mXDn2F|2^31|1:1]
2019-02-19 13:23:23.731999 [DEBUG] switch_core_media.c:1804 looking for crypto suite [AEAD_AES_128_GCM_8]alias=[] in [5 AES_CM_128_HMAC_SHA1_80 inline:GKS3Pyolq2FNrLsVljrZWO3ziKdaRG+9G8mXDn2F|2^31|1:1]
2019-02-19 13:23:23.731999 [DEBUG] switch_core_media.c:1804 looking for crypto suite [AES_256_CM_HMAC_SHA1_80]alias=[AES_CM_256_HMAC_SHA1_80] in [5 AES_CM_128_HMAC_SHA1_80 inline:GKS3Pyolq2FNrLsVljrZWO3ziKdaRG+9G8mXDn2F|2^31|1:1]
2019-02-19 13:23:23.731999 [DEBUG] switch_core_media.c:1804 looking for crypto suite [AES_192_CM_HMAC_SHA1_80]alias=[AES_CM_192_HMAC_SHA1_80] in [5 AES_CM_128_HMAC_SHA1_80 inline:GKS3Pyolq2FNrLsVljrZWO3ziKdaRG+9G8mXDn2F|2^31|1:1]
2019-02-19 13:23:23.731999 [DEBUG] switch_core_media.c:1804 looking for crypto suite [AES_CM_128_HMAC_SHA1_80]alias=[] in [5 AES_CM_128_HMAC_SHA1_80 inline:GKS3Pyolq2FNrLsVljrZWO3ziKdaRG+9G8mXDn2F|2^31|1:1]
2019-02-19 13:23:23.731999 [DEBUG] switch_core_media.c:1813 Found suite AES_CM_128_HMAC_SHA1_80
2019-02-19 13:23:23.731999 [DEBUG] switch_core_media.c:1883 Set Remote Key [5 AES_CM_128_HMAC_SHA1_80 inline:GKS3Pyolq2FNrLsVljrZWO3ziKdaRG+9G8mXDn2F|2^31|1:1]
2019-02-19 13:23:23.731999 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G7221:102:16000:20:24000:1]/[G7221:107:16000:20:24000:1]
2019-02-19 13:23:23.731999 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [G7221:107:16000:20:24000:1] ++++ is saved as a match
2019-02-19 13:23:23.731999 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G7221:102:16000:20:24000:1]/[G722:9:8000:20:64000:1]
2019-02-19 13:23:23.731999 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G7221:102:16000:20:24000:1]/[PCMU:0:8000:20:64000:1]
2019-02-19 13:23:23.731999 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G7221:102:16000:20:24000:1]/[PCMA:8:8000:20:64000:1]
2019-02-19 13:23:23.731999 [DEBUG] switch_core_media.c:5394 Set telephone-event payload to 101@8000
2019-02-19 13:23:23.731999 [DEBUG] switch_core_media.c:3781 Set Codec sofia/internal/User.Name(a)domain.tld G7221/16000 20 ms 320 samples 24000 bits 1 channels
2019-02-19 13:23:23.731999 [DEBUG] switch_core_codec.c:111 sofia/internal/User.Name(a)domain.tld Original read codec set to G7221:107
2019-02-19 13:23:23.731999 [DEBUG] switch_core_media.c:5795 sofia/internal/User.Name(a)domain.tld Set 2833 dtmf send payload to 101 recv payload to 101
2019-02-19 13:23:23.731999 [DEBUG] switch_core_media.c:8511 AUDIO RTP [sofia/internal/User.Name(a)domain.tld] XXX.XXX.XXX.XXX port 26804 -> YYY.YYY.YYY.YYY port 5380 codec: 102 ms: 20
2019-02-19 13:23:23.731999 [DEBUG] switch_rtp.c:4300 Starting timer [soft] 320 bytes per 20ms
2019-02-19 13:23:23.731999 [DEBUG] switch_core_media.c:8731 Activating RTCP PORT 5381
2019-02-19 13:23:23.731999 [DEBUG] switch_rtp.c:4696 RTCP send rate is: 500 and packet rate is: 20000 Remote Port: 5381
2019-02-19 13:23:23.731999 [DEBUG] switch_rtp.c:2572 Setting RTCP remote addr to YYY.YYY.YYY.YYY:5381 2
2019-02-19 13:23:23.731999 [DEBUG] switch_core_media.c:8815 sofia/internal/User.Name(a)domain.tld Set 2833 dtmf send payload to 101
2019-02-19 13:23:23.731999 [DEBUG] switch_core_media.c:8822 sofia/internal/User.Name(a)domain.tld Set 2833 dtmf receive payload to 101
2019-02-19 13:23:23.731999 [DEBUG] switch_core_media.c:8845 sofia/internal/User.Name(a)domain.tld Set rtp dtmf delay to 40
2019-02-19 13:23:23.731999 [DEBUG] switch_core_media.c:1495 LIFETIME found in |2^31|1:1, base 2 exp 31
2019-02-19 13:23:23.731999 [DEBUG] switch_core_media.c:1502 MKI found in |2^31|1:1, id 1 size 1
2019-02-19 13:23:23.731999 [DEBUG] switch_core_media.c:1495 LIFETIME found in |2^31|1:1, base 2 exp 31
2019-02-19 13:23:23.731999 [DEBUG] switch_core_media.c:1502 MKI found in |2^31|1:1, id 1 size 1
2019-02-19 13:23:23.731999 [INFO] switch_rtp.c:4104 Activating audio Secure RTP SEND (with MKI)
2019-02-19 13:23:23.731999 [DEBUG] switch_core_sqldb.c:2617 Secure Type: srtp:sdes:AES_CM_128_HMAC_SHA1_80
2019-02-19 13:23:23.731999 [INFO] switch_rtp.c:4082 Activating audio Secure RTP RECV (with MKI)
2019-02-19 13:23:23.731999 [DEBUG] switch_core_sqldb.c:2617 Secure Type: srtp:sdes:AES_CM_128_HMAC_SHA1_80
Call to Softphone
----------------------------------------------------
recv 1860 bytes from udp/[XXX.XXX.XXX.XXX]:5060 at 13:23:25.884591:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP XXX.XXX.XXX.XXX:5062;received=XXX.XXX.XXX.XXX;rport=5062;branch=z9hG4bKH13aN0H9550Ue
Content-Length: 428
P-Asserted-Identity: <sip:User.Name@domain.tld>, <tel:+11111111111;ext=1111>
From: "Extension 1000" <sip:1000@fs01.domain.tld>;tag=vvZQ9m8H03Npp
To: <sip:User.Name@domain.tld>;epid=111ee812f0;tag=1f0cd7c868
Call-ID: 5eaff2fd-aeec-1237-6aaa-00155d018038
CSeq: 737508 INVITE
Record-Route: <sip:ucs.domain.tld:5061;transport=tls;ms-fe=server3.domain.tld;opaque=state:T;lr>
Record-Route: <sip:XXX.XXX.XXX.XXX:5061;transport=tls;r2=on;lr>
Record-Route: <sip:XXX.XXX.XXX.XXX;r2=on;lr>
Contact: <sip:User.Name@domain.tld;opaque=user:epid:Xq6LHtQWXFWBMxOY6SkY-wAA;gruu>
User-Agent: UCCAPI/15.0.5093.1000 OC/15.0.5111.1000 (Skype for Business)
Supported: histinfo
Supported: ms-safe-transfer
Supported: ms-dialog-route-set-update
Allow: INVITE, BYE, ACK, CANCEL, INFO, UPDATE, REFER, NOTIFY, BENOTIFY, OPTIONS
Session-Expires: 720;refresher=uac
ms-endpoint-location-data: NetworkScope;ms-media-location-type=Intranet
Supported: ms-bypass
Supported: replaces
Content-Type: application/sdp
ms-application-via: ms-udc.cdr%3D70847bfc9ab1b8a46ead5d92c6ad493a%3A6%3Bconvhist%3D0%3A6;ms-pool=ucs.domain.tld;ms-application=http%3A%2F%2Fwww.microsoft.com%2FLCS%2FUdcAgent;ms-server=server3.domain.tld
v=0
o=- 0 1 IN IP4 ZZZ.ZZZ.ZZZ.ZZZ
s=FreeSWITCH
c=IN IP4 ZZZ.ZZZ.ZZZ.ZZZ
b=CT:99980
t=0 0
m=audio 5407 RTP/SAVP 102 9 0 8 101
a=crypto:5 AES_CM_128_HMAC_SHA1_80 inline:Pb70Q8VAa0lf1GNvKwjxRjUsK3pu1L28ga4pdn7s|2^31|1:1
a=maxptime:200
a=rtpmap:102 G7221/16000
a=fmtp:102 bitrate=24000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtcp-mux
a=ptime:20
------------------------------------------------------------------------
2019-02-19 13:23:25.431998 [INFO] sofia.c:1356 sofia/internal/User.Name(a)domain.tld Update Callee ID to "User.Name" <User.Name>
2019-02-19 13:23:25.431998 [DEBUG] sofia.c:7291 Channel sofia/internal/User.Name(a)domain.tld entering state [completing][200]
2019-02-19 13:23:25.431998 [DEBUG] sofia.c:7301 Remote SDP:
v=0
o=- 0 1 IN IP4 ZZZ.ZZZ.ZZZ.ZZZ
s=FreeSWITCH
c=IN IP4 ZZZ.ZZZ.ZZZ.ZZZ
b=CT:99980
t=0 0
m=audio 5407 RTP/SAVP 102 9 0 8 101
a=rtpmap:102 G7221/16000
a=fmtp:102 bitrate=24000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=crypto:5 AES_CM_128_HMAC_SHA1_80 inline:Pb70Q8VAa0lf1GNvKwjxRjUsK3pu1L28ga4pdn7s|2^31|1:1
a=maxptime:200
a=rtcp-mux
a=ptime:20
Thanks,
Denis