After asterisk upgrade from 13.18 to 13.19, polycom phones not working

tonyg · March 20, 2018, 3:36pm

hi, i am using FreePBX 14.0.1.36 with asterisk 13.19.1 with pjsip endpoints. over the weekend, i applied all distro and freepbx module updates. after restarting the pbx…this included an upgrade for asterisk from 13.18 to 13.19, i noticed that the 3 polycom ip5000’s i have are showing unavailable in the “pjsip show contacts” list. the 90+ grandstream desk phones I have are not behaving this way and the poly’s were working fine prior. The polycom’s are using straight UDP (SIP) while my grandstream’s are TCP (SIP-TLS and SRTP). I am looking at the “pjsip set logging on” and i see the initial register fails but a followup register seems to be ok. When I try a call, the call sets up, the other party answers but no audio either direction.

I am not sure where to go from here, can someone point me in the right direction…here are some logs

Initial register:

uepbx1*CLI>
<— Received SIP request (534 bytes) from UDP:172.30.2.50:5060 —>
REGISTER sip:172.30.2.1:5060 SIP/2.0

Via: SIP/2.0/UDP 172.30.2.50;branch=z9hG4bK229b41cf2F2540

From: “Phoenix Conference Room” sip:5353@172.30.2.1;tag=5F2FA309-6B3DB3C2

To: sip:5353@172.30.2.1

CSeq: 1 REGISTER

Call-ID: 19557565-874811ce-41c6bf4b@172.30.2.50

Contact: sip:5353@172.30.2.50;methods=“INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER”

User-Agent: PolycomSoundStationIP-SSIP_5000-UA/4.1.1.0731

Accept-Language: en

Max-Forwards: 70

Expires: 120

Content-Length: 0

uepbx1*CLI>
<— Transmitting SIP response (516 bytes) to UDP:172.30.2.50:5060 —>
SIP/2.0 401 Unauthorized

Via: SIP/2.0/UDP 172.30.2.50;rport=5060;received=172.30.2.50;branch=z9hG4bK229b41cf2F2540

Call-ID: 19557565-874811ce-41c6bf4b@172.30.2.50

From: “Phoenix Conference Room” sip:5353@172.30.2.1;tag=5F2FA309-6B3DB3C2

To: sip:5353@172.30.2.1;tag=z9hG4bK229b41cf2F2540

CSeq: 1 REGISTER

WWW-Authenticate: Digest realm=“asterisk”,nonce=“1521555366/f3db9f9aedd38b761bd2e53663ab6171”,opaque=“0232a6743103aea9”,algorithm=md5,qop=“auth”

Server: FPBX-14.0.1.36(13.19.1)

Content-Length: 0

uepbx1*CLI>
<— Received SIP request (808 bytes) from UDP:172.30.2.50:5060 —>
REGISTER sip:172.30.2.1:5060 SIP/2.0

Via: SIP/2.0/UDP 172.30.2.50;branch=z9hG4bK63be8ec751E5501

From: “Phoenix Conference Room” sip:5353@172.30.2.1;tag=5F2FA309-6B3DB3C2

To: sip:5353@172.30.2.1

CSeq: 2 REGISTER

Call-ID: 19557565-874811ce-41c6bf4b@172.30.2.50

Contact: sip:5353@172.30.2.50;methods=“INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER”

User-Agent: PolycomSoundStationIP-SSIP_5000-UA/4.1.1.0731

Accept-Language: en

Authorization: Digest username=“5353”, realm=“asterisk”, nonce=“1521555366/f3db9f9aedd38b761bd2e53663ab6171”, qop=auth, cnonce=“zjueJVIz3mYQTA7”, nc=00000001, opaque=“0232a6743103aea9”, uri=“sip:172.30.2.1:5060”, response=“23b42f427c2954061632412cd23bdf4e”, algorithm=MD5

Max-Forwards: 70

Expires: 120

Content-Length: 0

uepbx1*CLI>
<— Transmitting SIP response (462 bytes) to UDP:172.30.2.50:5060 —>
SIP/2.0 200 OK

Via: SIP/2.0/UDP 172.30.2.50;rport=5060;received=172.30.2.50;branch=z9hG4bK63be8ec751E5501

Call-ID: 19557565-874811ce-41c6bf4b@172.30.2.50

From: “Phoenix Conference Room” sip:5353@172.30.2.1;tag=5F2FA309-6B3DB3C2

To: sip:5353@172.30.2.1;tag=z9hG4bK63be8ec751E5501

CSeq: 2 REGISTER

Date: Tue, 20 Mar 2018 14:16:06 GMT

Contact: sip:5353@172.30.2.50:5060;expires=119

Expires: 120

Server: FPBX-14.0.1.36(13.19.1)

Content-Length: 0

uepbx1*CLI>
<— Transmitting SIP request (420 bytes) to UDP:172.30.2.50:5060 —>
OPTIONS sip:5353@172.30.2.50:5060 SIP/2.0

Via: SIP/2.0/UDP 172.30.200.1:5060;rport;branch=z9hG4bKPj9b99e675-5889-4ac9-b537-0c8712a86138

From: sip:5353@172.30.2.1;tag=60a1ff0f-3548-4fdc-9e0d-5cc7b3807706

To: sip:5353@172.30.2.50

Contact: sip:5353@172.30.200.1:5060

Call-ID: 056dd420-0497-40a2-bf14-d882a61ae6ac

CSeq: 24538 OPTIONS

Max-Forwards: 70

User-Agent: FPBX-14.0.1.36(13.19.1)

Content-Length: 0

<— Transmitting SIP request (630 bytes) to UDP:172.30.2.50:5060 —>
NOTIFY sip:5353@172.30.2.50:5060 SIP/2.0

Via: SIP/2.0/UDP 172.30.200.1:5060;rport;branch=z9hG4bKPje47c0a10-b8f9-4ea2-ad6a-f34f9aba58df

From: sip:5353@172.30.2.1;tag=2995f3df-9e99-4e02-8277-5ec46a0d7903

To: sip:5353@172.30.2.50

Contact: sip:5353@172.30.200.1:5060

Call-ID: 650d92e5-1d92-46ce-ba16-05ae2a1a2e62

CSeq: 3416 NOTIFY

Subscription-State: terminated

Event: message-summary

Allow-Events: presence, dialog, message-summary, refer

Max-Forwards: 70

User-Agent: FPBX-14.0.1.36(13.19.1)

Content-Type: application/simple-message-summary

Content-Length: 48

Messages-Waiting: no

Voice-Message: 0/0 (0/0)

call attempt:

uepbx1*CLI>
<— Received SIP request (932 bytes) from UDP:172.30.2.50:5060 —>
INVITE sip:5332@172.30.2.1:5060;user=phone SIP/2.0

Via: SIP/2.0/UDP 172.30.2.50;branch=z9hG4bK38dbdea3A50E2024

From: “Phoenix Conference Room” sip:5353@172.30.2.1;tag=B1AC897D-7F5544C6

To: sip:5332@172.30.2.1;user=phone

CSeq: 1 INVITE

Call-ID: 3471c599-6e849792-2e8157df@172.30.2.50

Contact: sip:5353@172.30.2.50

Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER

User-Agent: PolycomSoundStationIP-SSIP_5000-UA/4.1.1.0731

Accept-Language: en

Supported: 100rel,replaces

Allow-Events: conference,talk,hold

Max-Forwards: 70

Content-Type: application/sdp

Content-Length: 292

v=0

o=- 1521555777 1521555777 IN IP4 172.30.2.50

s=Polycom IP Phone

c=IN IP4 172.30.2.50

t=0 0

a=sendrecv

m=audio 2226 RTP/AVP 0 8 18 9 127

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:127 telephone-event/8000

uepbx1*CLI>
<— Transmitting SIP response (529 bytes) to UDP:172.30.2.50:5060 —>
SIP/2.0 401 Unauthorized

Via: SIP/2.0/UDP 172.30.2.50;rport=5060;received=172.30.2.50;branch=z9hG4bK38dbdea3A50E2024

Call-ID: 3471c599-6e849792-2e8157df@172.30.2.50

From: “Phoenix Conference Room” sip:5353@172.30.2.1;tag=B1AC897D-7F5544C6

To: sip:5332@172.30.2.1;user=phone;tag=z9hG4bK38dbdea3A50E2024

CSeq: 1 INVITE

WWW-Authenticate: Digest realm=“asterisk”,nonce=“1521555778/1ce06a0e0a2c9043755bbc61ae1055ae”,opaque=“3b34662d7d8eeab1”,algorithm=md5,qop=“auth”

Server: FPBX-14.0.1.36(13.19.1)

Content-Length: 0

uepbx1*CLI>
<— Received SIP request (565 bytes) from UDP:172.30.2.50:5060 —>
ACK sip:5332@172.30.2.1:5060;user=phone SIP/2.0

Via: SIP/2.0/UDP 172.30.2.50;branch=z9hG4bK38dbdea3A50E2024

From: “Phoenix Conference Room” sip:5353@172.30.2.1;tag=B1AC897D-7F5544C6

To: sip:5332@172.30.2.1;user=phone;tag=z9hG4bK38dbdea3A50E2024

CSeq: 1 ACK

Call-ID: 3471c599-6e849792-2e8157df@172.30.2.50

Contact: sip:5353@172.30.2.50

Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER

User-Agent: PolycomSoundStationIP-SSIP_5000-UA/4.1.1.0731

Accept-Language: en

Max-Forwards: 70

Content-Length: 0

uepbx1*CLI>
<— Received SIP request (1221 bytes) from UDP:172.30.2.50:5060 —>
INVITE sip:5332@172.30.2.1:5060;user=phone SIP/2.0

Via: SIP/2.0/UDP 172.30.2.50;branch=z9hG4bK8b279290C67BA2F5

From: “Phoenix Conference Room” sip:5353@172.30.2.1;tag=B1AC897D-7F5544C6

To: sip:5332@172.30.2.1;user=phone

CSeq: 2 INVITE

Call-ID: 3471c599-6e849792-2e8157df@172.30.2.50

Contact: sip:5353@172.30.2.50

Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER

User-Agent: PolycomSoundStationIP-SSIP_5000-UA/4.1.1.0731

Accept-Language: en

Supported: 100rel,replaces

Allow-Events: conference,talk,hold

Authorization: Digest username=“5353”, realm=“asterisk”, nonce=“1521555778/1ce06a0e0a2c9043755bbc61ae1055ae”, qop=auth, cnonce=“fSD1YRHONCYBdFo”, nc=00000001, opaque=“3b34662d7d8eeab1”, uri=“sip:5332@172.30.2.1:5060;user=phone”, response=“30c996998c2ffe50709ef86e8c6e44fd”, algorithm=MD5

Max-Forwards: 70

Content-Type: application/sdp

Content-Length: 292

v=0

o=- 1521555777 1521555777 IN IP4 172.30.2.50

s=Polycom IP Phone

c=IN IP4 172.30.2.50

t=0 0

a=sendrecv

m=audio 2226 RTP/AVP 0 8 18 9 127

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:127 telephone-event/8000

uepbx1*CLI>
<— Transmitting SIP response (348 bytes) to UDP:172.30.2.50:5060 —>
SIP/2.0 100 Trying

Via: SIP/2.0/UDP 172.30.2.50;rport=5060;received=172.30.2.50;branch=z9hG4bK8b279290C67BA2F5

Call-ID: 3471c599-6e849792-2e8157df@172.30.2.50

From: “Phoenix Conference Room” sip:5353@172.30.2.1;tag=B1AC897D-7F5544C6

To: sip:5332@172.30.2.1;user=phone

CSeq: 2 INVITE

Server: FPBX-14.0.1.36(13.19.1)

Content-Length: 0

jcolp · March 20, 2018, 3:41pm

Check the output of “rtp set debug on” and see if the traffic is being received and is being sent to the correct IP address.

malcolmd · March 20, 2018, 3:41pm

Also, that’s how REGISTER works. REGISTER w/ no auth. 401. REGISTER w/ auth. 200 OK. That’s all normal.

tonyg · March 20, 2018, 5:26pm

jcolp, malcolmd, thanks for responding quickly! in an effort to resolve this, i tried deleting one of the affected extension and recreating it. now, that extension does not authenticate at all. is there a way to debug specifically what about the config is preventing the authentication…ie, password, id etc?

thanks>

<— Received SIP request (809 bytes) from UDP:172.30.2.50:5060 —>
REGISTER sip:172.30.2.1:5060 SIP/2.0
Via: SIP/2.0/UDP 172.30.2.50;branch=z9hG4bKb5b81ce07FEECF69
From: “Phoenix Conference Room” sip:5353@172.30.2.1;tag=D331BA51-9569C89E
To: sip:5353@172.30.2.1
CSeq: 2 REGISTER
Call-ID: 9349253d-fc83673a-4be7df2b@172.30.2.50
Contact: sip:5353@172.30.2.50;methods=“INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER”
User-Agent: PolycomSoundStationIP-SSIP_5000-UA/4.1.1.0731
Accept-Language: en
Authorization: Digest username=“5353”, realm=“asterisk”, nonce=“1521566998/353bfb3cd0486ef8ac86939724e88137”, qop=auth, cnonce=“FqWuKRiGpiu9H/R”, nc=00000001, opaque=“379408c52796067b”, uri=“sip:172.30.2.1:5060”, response=“30b260910713a8753bbdcd3427cbf0ce”, algorithm=MD5
Max-Forwards: 70
Expires: 120
Content-Length: 0

[2018-03-20 13:29:58] NOTICE[27359]: res_pjsip/pjsip_distributor.c:649 log_failed_request: Request ‘REGISTER’ from ‘“Phoenix Conference Room” sip:5353@172.30.2.1’ failed for ‘172.30.2.50:5060’ (callid: 9349253d-fc83673a-4be7df2b@172.30.2.50) - Failed to authenticate
<— Transmitting SIP response (520 bytes) to UDP:172.30.2.50:5060 —>
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 172.30.2.50;rport=5060;received=172.30.2.50;branch=z9hG4bKb5b81ce07FEECF69
Call-ID: 9349253d-fc83673a-4be7df2b@172.30.2.50
From: “Phoenix Conference Room” sip:5353@172.30.2.1;tag=D331BA51-9569C89E
To: sip:5353@172.30.2.1;tag=z9hG4bKb5b81ce07FEECF69
CSeq: 2 REGISTER
WWW-Authenticate: Digest realm=“asterisk”,nonce=“1521566998/353bfb3cd0486ef8ac86939724e88137”,opaque=“622c80887b41b88e”,algorithm=md5,qop=“auth”
Server: FPBX-14.0.1.36(13.19.1)
Content-Length: 0

jcolp · March 20, 2018, 5:35pm

You would need to check the configuration itself and the configuration on the device. The message is usually the result of an incorrect password.

david551 · March 20, 2018, 5:46pm

403 would be an incorrect password. If this log is complete, it means that the phone doesn’t have a password at all, so is getting stuck when asked for one.

tonyg · March 20, 2018, 5:53pm

it hard to say for sure, but i have checked the pjsip config file with the config file the phone is downloading…the passwords are the same. i am looking at a packet capture now, and i don’t see where the password is in the packet…is it md5 hashed ?

jcolp · March 20, 2018, 6:34pm

Yes, it is md5 hashed using different components. I don’t have it handy, but it is documented online. It is not communicated in clear text as it would be easy for someone to get credentials.