Asterisk returns 401 for correctly authenticated extensions when calling

vncz · October 24, 2018, 5:14pm

Hello guys — I’ve been an happy user of Asterisk so far and I’m now facing an issue I haven’t been able to resolve yet. I was wondering/hoping whether someone here faced the same issue and maybe can help me.

I’ve one user that is working on another office which is connected through an OpenVPN connection.

The guy is able to correctly authenticate in the Asterisk server and even correctly receive calls; however when he tries to make any call; it does not matter if internal or external, Asterisk is answering back with 401 Unauthorized.

I’ve been trying to have a look into the logs by enabling the maximum debug level allowed in the platform it’s clearly returning 401; the strange part is that it does not really tell you the reason, so I have NO idea what’s wrong here:

<--- Received SIP request (1180 bytes) from UDP:10.100.104.6:50218 --->
INVITE sip:3932551907@172.18.19.127;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 93.34.90.137:45058;branch=z9hG4bK-524287-1---7c1bde5ea092c950;rport
Max-Forwards: 70
Contact: <sip:993@93.34.90.137:45058;transport=UDP>
To: <sip:3932551907@172.18.19.127;transport=UDP>
From: <sip:993@172.18.19.127;transport=UDP>;tag=367d205b
Call-ID: WsV2HuMEeWqQoBezh9Plkg..
CSeq: 1 INVITE
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Content-Type: application/sdp
User-Agent: Z 5.2.19 rv2.8.99
Allow-Events: presence, kpml, talk
Content-Length: 601

v=0
o=Z 0 0 IN IP4 93.34.90.137
s=Z
c=IN IP4 93.34.90.137
t=0 0
m=audio 45522 RTP/AVP 106 9 3 111 0 8 97 110 112 98 101 100 99 102
a=rtpmap:106 opus/48000/2
a=fmtp:106 minptime=20; cbr=1; maxaveragebitrate=40000; useinbandfec=1
a=rtpmap:111 speex/16000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=20
a=rtpmap:110 speex/8000
a=rtpmap:112 speex/32000
a=rtpmap:98 telephone-event/48000
a=fmtp:98 0-16
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:100 telephone-event/16000
a=fmtp:100 0-16
a=rtpmap:99 telephone-event/32000
a=fmtp:99 0-16
a=rtpmap:102 G726-32/8000
a=sendrecv

[2018-10-24 18:58:08] DEBUG[10094]: res_pjsip/pjsip_distributor.c:383 find_dialog: Could not find matching transaction for Request msg INVITE/cseq=1 (rdata0x73d157b4)
[2018-10-24 18:58:08] DEBUG[10094]: res_pjsip/pjsip_distributor.c:461 ast_sip_get_distributor_serializer: Calculated serializer pjsip/distributor-00000042 to use for Request msg INVITE/cseq=1 (rdata0x73d157b4)
[2018-10-24 18:58:08] DEBUG[10095]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.100.104.6' into...
[2018-10-24 18:58:08] DEBUG[10095]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.100.104.6' and port ''.
[2018-10-24 18:58:08] DEBUG[10095]: res_pjsip_endpoint_identifier_ip.c:245 ip_identify_match_check: Source address 10.100.104.6:50218 does not match identify '5406086557'
[2018-10-24 18:58:08] DEBUG[10095]: res_pjsip_endpoint_identifier_ip.c:245 ip_identify_match_check: Source address 10.100.104.6:50218 does not match identify '5406034193'
[2018-10-24 18:58:08] DEBUG[10095]: res_pjsip_endpoint_identifier_ip.c:245 ip_identify_match_check: Source address 10.100.104.6:50218 does not match identify '5341696'
[2018-10-24 18:58:08] DEBUG[10095]: res_pjsip_endpoint_identifier_ip.c:245 ip_identify_match_check: Source address 10.100.104.6:50218 does not match identify '5406005158'
[2018-10-24 18:58:08] DEBUG[10095]: res_pjsip_endpoint_identifier_ip.c:245 ip_identify_match_check: Source address 10.100.104.6:50218 does not match identify 'UalaImmo'
[2018-10-24 18:58:08] DEBUG[10095]: res_pjsip_endpoint_identifier_ip.c:245 ip_identify_match_check: Source address 10.100.104.6:50218 does not match identify '0510216176'
[2018-10-24 18:58:08] DEBUG[10095]: res_pjsip_endpoint_identifier_ip.c:240 ip_identify_match_check: Source address 10.100.104.6:50218 matches identify '993-identify'
[2018-10-24 18:58:08] DEBUG[10095]: res_pjsip_endpoint_identifier_ip.c:273 common_identify: Identify '993-identify' SIP message matched to endpoint 993
[2018-10-24 18:58:08] DEBUG[10095]: res_pjsip_authenticator_digest.c:454 digest_check_auth: Using default realm 'asterisk' on incoming auth '993-auth'.
[2018-10-24 18:58:08] DEBUG[10095]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '172.18.19.127' into...
[2018-10-24 18:58:08] DEBUG[10095]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '172.18.19.127' and port ''.
[2018-10-24 18:58:08] DEBUG[10095]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.100.104.6' into...
[2018-10-24 18:58:08] DEBUG[10095]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.100.104.6' and port ''.
[2018-10-24 18:58:08] DEBUG[10095]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.100.104.6' into...
[2018-10-24 18:58:08] DEBUG[10095]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.100.104.6' and port ''.
[2018-10-24 18:58:08] DEBUG[10095]: res_pjsip_nat.c:271 nat_on_tx_message: Request is being sent to local address, skipping NAT manipulation
<--- Transmitting SIP response (512 bytes) to UDP:10.100.104.6:50218 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 93.34.90.137:45058;rport=50218;received=10.100.104.6;branch=z9hG4bK-524287-1---7c1bde5ea092c950
Call-ID: WsV2HuMEeWqQoBezh9Plkg..
From: <sip:993@172.18.19.127>;tag=367d205b
To: <sip:3932551907@172.18.19.127>;tag=z9hG4bK-524287-1---7c1bde5ea092c950
CSeq: 1 INVITE
WWW-Authenticate: Digest  realm="asterisk",nonce="1540400288/90ebde0908b76e093a1a141669e5a1b9",opaque="327495263dc09c32",algorithm=md5,qop="auth"
Server: FPBX-14.0.4.1(13.23.0)
Content-Length:  0


<--- Received SIP request (363 bytes) from UDP:10.100.104.6:50218 --->
ACK sip:3932551907@172.18.19.127;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 93.34.90.137:45058;branch=z9hG4bK-524287-1---7c1bde5ea092c950;rport
Max-Forwards: 70
To: <sip:3932551907@172.18.19.127>;tag=z9hG4bK-524287-1---7c1bde5ea092c950
From: <sip:993@172.18.19.127;transport=UDP>;tag=367d205b
Call-ID: WsV2HuMEeWqQoBezh9Plkg..
CSeq: 1 ACK
Content-Length: 0

I can also see that the phone is answering with ACK and aborting the call; but I can’t really figure out the reason - the user seems to be identified correctly!

Any hints on how to move forward with this?

jcolp · October 24, 2018, 5:17pm

You haven’t shown the actual configuration for the endpoint, so can’t really answer on why it is doing that.

vncz · October 24, 2018, 5:18pm

Here’s the current configuration:

[993]
type=endpoint
aors=993
auth=993-auth
tos_audio=ef
tos_video=af41
cos_audio=5
cos_video=4
allow=ulaw,alaw,gsm,g726,g722
context=from-internal
callerid=Gaetano <993>
dtmf_mode=rfc4733
mailboxes=993@device
mwi_subscribe_replaces_unsolicited=yes
aggregate_mwi=yes
use_avpf=no
rtcp_mux=no
ice_support=no
media_use_received_transport=no
trust_id_inbound=yes
media_encryption=no
timers=yes
media_encryption_optimistic=no
send_pai=yes
rtp_symmetric=yes
rewrite_contact=yes
force_rport=yes
language=it
one_touch_recording=on
record_on_feature=apprecord
record_off_feature=apprecord

However regardless of that — shouldn’t the logs tell you something about why the response 401 is being returned? That would have been super helpful!

P.S: I’m on Asterisk 13 — maybe you guys fixed this already in the following versions!

jcolp · October 24, 2018, 5:19pm

You’ve got an auth set, which is used for inbound authentication. Asterisk appears to be challenging for authentication as configured. It would be up to the endpoint to then send the INVITE again with credentials.

vncz · October 24, 2018, 5:20pm

What I do not get though is that all the other extensions have been configured in the same way and they’re using the same client; no issues at all. The only one having such problem is this one, which is connected in VPN.

I’m willing to remove the auth — shall I just remove auth=993-auth line?

jcolp · October 24, 2018, 5:21pm

That will disable authentication. As for why it’s not working, from the Asterisk side it is doing as it should.

vncz · October 24, 2018, 5:22pm

I’m going to give it a try and see what happens.

It seems to be a known issue https://github.com/BelledonneCommunications/linphone-iphone/issues/195 but I really do not get why only this extension is having such problem.

vncz · October 24, 2018, 7:53pm

By removing that line, it seems like the call gets processed correctly. Thanks for the help.

I still do not understand why such issue is not happening for all the other clients in the office. It seems to be happening exclusively to the client connected via VPN.