Local phones start failing to authenticate after upgrade to FreePBX17

pruy · August 19, 2024, 8:17pm

I just upgraded to 17.
Smooth upgrade, no issues.
Now all my phones fail to authenticate.
(4 Mitel/Astra Dect, 1 Grandstream WLAN, 1 Grandstream Video, 1 old Snom 260, 1 Softphone)

Registration and connections to and from my providers (so any external connections) are working properly.

All devices are using pjsip (and had done so before migration).
Thus not a sip->pjsip conversion issue.

If I add a new (soft-)phone via GUI it also fails to register using the same errors.
Looks something is fundamentally wrong, but I fyet failed to figure out any reason.

Any hints where to look to get more insight into the problem?
Thanks for any help.

Rainer

The relevant portion from the log seems to me:

[2024-08-19 08:46:14] DEBUG[17449] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '299' domain '10.202.10.2'
[2024-08-19 08:46:14] DEBUG[17449] res_pjsip_endpoint_identifier_user.c: Identified by From username '299' domain '10.202.10.2'
[2024-08-19 08:46:14] DEBUG[17449] res_pjsip_authenticator_digest.c: Using default realm 'asterisk' on incoming auth '299-auth'.
[2024-08-19 08:46:14] DEBUG[17449] res_pjsip_authenticator_digest.c: Calculated nonce 1724049974/c5c2ffba6a8dfc6e488b122751671188. Actual nonce is 1724049974/c5c2ffba6a8dfc6e488b122751671188
[2024-08-19 08:46:14] DEBUG[17449] res_pjsip_authenticator_digest.c: Realm: asterisk  Username: 299  Result: FAIL

The full context from log:

[2024-08-19 08:46:14] VERBOSE[17447] res_pjsip_logger.c: <--- Received SIP request (837 bytes) from UDP:10.202.3.100:53519 --->
REGISTER sip:10.202.10.2 SIP/2.0
Via: SIP/2.0/UDP 10.202.3.100:53519;branch=z9hG4bKmuvfnzZP30SY;rport
From: "BU11" <sip:[email protected]>;tag=76DDpvSJCtgg
To: "BU11" <sip:[email protected]>
Call-ID: rA-ElBb49t1vNcXt8I9i
CSeq: 1592 REGISTER
Contact: <sip:[email protected]:55390;x-reg=007B06BF091460CF>;expires=0
Contact: <sip:[email protected]:53519;x-reg=A054BF48FE0A94EA>;expires=600
Content-Length: 0
User-Agent: Sipnetic/1.1.3 Android
Supported: path
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,INFO,SUBSCRIBE,NOTIFY,REFER,PRACK,MESSAGE
Authorization: Digest username="299",realm="asterisk",nonce="1724049974/c5c2ffba6a8dfc6e488b122751671188",opaque="70cac5556cb9dd44",uri="sip:10.202.10.2",cnonce="16307bc79999014960b61b50090d32d6",qop=auth,nc=00000003,algorithm=MD5,response="3f06fad11152b5a03d60c9d75d8e70b2"
Max-Forwards: 70


[2024-08-19 08:46:14] DEBUG[17447] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=1592 (rdata0x7f0268006078)
[2024-08-19 08:46:14] DEBUG[17447] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-0000003a to use for Request msg REGISTER/cseq=1592 (rdata0x7f0268006078)
[2024-08-19 08:46:14] DEBUG[17449] netsock2.c: Splitting '10.202.3.100' into...
[2024-08-19 08:46:14] DEBUG[17449] netsock2.c: ...host '10.202.3.100' and port ''.
[2024-08-19 08:46:14] DEBUG[17449] res_pjsip_endpoint_identifier_ip.c: Source address 10.202.3.100:53519 does not match identify 'Vodafone-542978'
[2024-08-19 08:46:14] DEBUG[17449] res_pjsip_endpoint_identifier_ip.c: Source address 10.202.3.100:53519 does not match identify 'Vodafone-9953051'
[2024-08-19 08:46:14] DEBUG[17449] res_pjsip_endpoint_identifier_ip.c: Source address 10.202.3.100:53519 does not match identify 'Vodafone-542903'
[2024-08-19 08:46:14] DEBUG[17449] res_pjsip_endpoint_identifier_ip.c: Source address 10.202.3.100:53519 does not match identify 'Vodafone-9952564'
[2024-08-19 08:46:14] DEBUG[17449] res_pjsip_endpoint_identifier_ip.c: Source address 10.202.3.100:53519 does not match identify 'Vodafone-542977'
[2024-08-19 08:46:14] DEBUG[17449] res_pjsip_endpoint_identifier_ip.c: Source address 10.202.3.100:53519 does not match identify 'Vodafone-9953007'
[2024-08-19 08:46:14] DEBUG[17449] res_pjsip_endpoint_identifier_ip.c: Source address 10.202.3.100:53519 does not match identify 'Sipgate6590590'
**[2024-08-19 08:46:14] DEBUG[17449] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '299' domain '10.202.10.2'**
**[2024-08-19 08:46:14] DEBUG[17449] res_pjsip_endpoint_identifier_user.c: Identified by From username '299' domain '10.202.10.2'**
**[2024-08-19 08:46:14] DEBUG[17449] res_pjsip_authenticator_digest.c: Using default realm 'asterisk' on incoming auth '299-auth'.**
**[2024-08-19 08:46:14] DEBUG[17449] res_pjsip_authenticator_digest.c: Calculated nonce 1724049974/c5c2ffba6a8dfc6e488b122751671188. Actual nonce is 1724049974/c5c2ffba6a8dfc6e488b122751671188**
**[2024-08-19 08:46:14] DEBUG[17449] res_pjsip_authenticator_digest.c: Realm: asterisk  Username: 299  Result: FAIL**
[2024-08-19 08:46:14] NOTICE[17449] res_pjsip/pjsip_distributor.c: Request 'REGISTER' from '"BU11" <sip:[email protected]>' failed for '10.202.3.100:53519' (callid: rA-ElBb49t1vNcXt8I9i) - Failed to authenticate
[2024-08-19 08:46:14] DEBUG[17449] netsock2.c: Splitting '10.202.10.2' into...
[2024-08-19 08:46:14] DEBUG[17449] netsock2.c: ...host '10.202.10.2' and port ''.
[2024-08-19 08:46:14] DEBUG[17449] netsock2.c: Splitting '10.202.3.100' into...
[2024-08-19 08:46:14] DEBUG[17449] netsock2.c: ...host '10.202.3.100' and port ''.
[2024-08-19 08:46:14] DEBUG[17449] netsock2.c: Splitting '10.202.3.100' into...
[2024-08-19 08:46:14] DEBUG[17449] netsock2.c: ...host '10.202.3.100' and port ''.
[2024-08-19 08:46:14] DEBUG[17449] res_pjsip_nat.c: Request is being sent to local address, skipping NAT manipulation
[2024-08-19 08:46:14] DEBUG[17449] netsock2.c: Splitting '10.202.3.100' into...
[2024-08-19 08:46:14] DEBUG[17449] netsock2.c: ...host '10.202.3.100' and port ''.
[2024-08-19 08:46:14] VERBOSE[17449] res_pjsip_logger.c: <--- Transmitting SIP response (487 bytes) to UDP:10.202.3.100:53519 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 10.202.3.100:53519;rport=53519;received=10.202.3.100;branch=z9hG4bKmuvfnzZP30SY
Call-ID: rA-ElBb49t1vNcXt8I9i
From: "BU11" <sip:[email protected]>;tag=76DDpvSJCtgg
To: "BU11" <sip:[email protected]>;tag=z9hG4bKmuvfnzZP30SY
CSeq: 1592 REGISTER
WWW-Authenticate: Digest realm="asterisk",nonce="1724049974/c5c2ffba6a8dfc6e488b122751671188",opaque="23d469d55b8c3340",algorithm=MD5,qop="auth"
Server: FPBX-17.0.19.1(21.4.1)
Content-Length:  0

pruy · August 21, 2024, 8:53pm

Still struggling…
To rule out any issues from migration,
I did a complete reinstall and
started adding my local phones manually (as sip devices):

Same problem, still authetication fails.
Related log:

[2024-08-21 22:26:30] VERBOSE[2646] res_pjsip_logger.c: <--- Received SIP request (778 bytes) from UDP:10.202.3.100:42424 --->
REGISTER sip:10.202.10.2 SIP/2.0
Via: SIP/2.0/UDP 10.202.3.100:42424;branch=z9hG4bKBJ46SNYcJXNp;rport
From: "BU11" <sip:[email protected]>;tag=9r1gEPdwYRxb
To: "BU11" <sip:[email protected]>
Call-ID: bW2jECQCZebkhIsEk5rZ
CSeq: 640 REGISTER
Contact: <sip:[email protected]:42424;x-reg=8CC394D71E997198>;expires=600
Content-Length: 0
Expires: 600
User-Agent: Sipnetic/1.1.3 Android
Supported: path
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,INFO,SUBSCRIBE,NOTIFY,REFER,PRACK,MESSAGE
Authorization: Digest username="299",realm="asterisk",nonce="1724271990/c099c157c38dc1ccb8aec052510e9194",opaque="5596ed5c61c41163",uri="sip:10.202.10.2",cnonce="4deac149db7fcfa8d5f50fad861f7e0a",qop=auth,nc=00000003,algorithm=MD5,response="cd1f71d869037299926edfd55ff2edd8"
Max-Forwards: 70


[2024-08-21 22:26:30] DEBUG[2646] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=640 (rdata0x7f49c8003048)
[2024-08-21 22:26:30] DEBUG[2646] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000031 to use for Request msg REGISTER/cseq=640 (rdata0x7f49c8003048)
[2024-08-21 22:26:30] DEBUG[12672] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against
[2024-08-21 22:26:30] DEBUG[12672] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '299' domain '10.202.10.2'
[2024-08-21 22:26:30] DEBUG[12672] res_pjsip_endpoint_identifier_user.c: Identified by From username '299' domain '10.202.10.2'
[2024-08-21 22:26:30] DEBUG[12672] res_pjsip_authenticator_digest.c: Using default realm 'asterisk' on incoming auth '299-auth'.
[2024-08-21 22:26:30] DEBUG[12672] res_pjsip_authenticator_digest.c: Calculated nonce 1724271990/c099c157c38dc1ccb8aec052510e9194. Actual nonce is 1724271990/c099c157c38dc1ccb8aec052510e9194
[2024-08-21 22:26:30] DEBUG[12672] res_pjsip_authenticator_digest.c: Realm: asterisk  Username: 299  Result: FAIL
[2024-08-21 22:26:30] NOTICE[12672] res_pjsip/pjsip_distributor.c: Request 'REGISTER' from '"BU11" <sip:[email protected]>' failed for '10.202.3.100:42424' (callid: bW2jECQCZebkhIsEk5rZ) - Failed to authenticate
[2024-08-21 22:26:30] VERBOSE[12672] res_pjsip_logger.c: <--- Transmitting SIP response (486 bytes) to UDP:10.202.3.100:42424 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 10.202.3.100:42424;rport=42424;received=10.202.3.100;branch=z9hG4bKBJ46SNYcJXNp
Call-ID: bW2jECQCZebkhIsEk5rZ
From: "BU11" <sip:[email protected]>;tag=9r1gEPdwYRxb
To: "BU11" <sip:[email protected]>;tag=z9hG4bKBJ46SNYcJXNp
CSeq: 640 REGISTER
WWW-Authenticate: Digest realm="asterisk",nonce="1724271990/c099c157c38dc1ccb8aec052510e9194",opaque="30467ddd1811fc84",algorithm=MD5,qop="auth"
Server: FPBX-17.0.19.1(21.4.1)
Content-Length:  0


[2024-08-21 22:26:30] DEBUG[5508] manager.c: Examining AMI event:
Event: ChallengeResponseFailed
Privilege: security,all
EventTV: 2024-08-21T22:26:30.619+0200
Severity: Error
Service: PJSIP
EventVersion: 1
AccountID: 299
SessionID: bW2jECQCZebkhIsEk5rZ
LocalAddress: IPV4/UDP/10.202.10.2/5060
RemoteAddress: IPV4/UDP/10.202.3.100/42424
Challenge: 1724271990/c099c157c38dc1ccb8aec052510e9194
Response: cd1f71d869037299926edfd55ff2edd8
ExpectedResponse:

I can not tell whther there should be an “ExpectedResponse” value with the core log?
If there should be one:

That authentication fails seems obvious
Why is there no “ExpectedResponse”?
How could I proceed analyzing?

I also recognized that “password” is filled by freepbx with a 32byze hex string.
This looks like what I would have expected with md5-cred, but auth_type is “userpass”.
Have not found a hint that this is a valid way of hiding cleartext passwords.

pruy · August 21, 2024, 8:56pm

Looks I found the culprit:

FreePBX is entering a hex value as password, not the clear text version.
Using this value with the related phone makes connection working again.

Thus, either FreePBX is falsely using a hex value with “userpass” auth
or it is halfway of using “md5” auth!

Any one knowing something about?

Summary:
When entering an own password with a user,
read the resulting hex value from asterisk and use this with your device.

system · August 28, 2024, 8:57pm

This topic was automatically closed 7 days after the last reply. New replies are no longer allowed.