SIP line logon failure 401: Unauthorized

[Graham_M]

Hi,

I am fairly new to Yate and would like some guidance on debugging an issue I can not solve.

My setup: I have two instances of Yate running as SBCs; the first is using the standard package in Ubuntu (5.4.0 1 r5880) while the second I have compiled from source (5.5.1 devel1 r6255).  I have two upstream registrations to DID Logic on each.

This works correctly for some time.  Each registers without issue and is able to make calls until at some stage, when we attempt to renew the registration, I get a 401 Unauthorised.

I have spoke to DID Logic and they suggest the issue is with the way we are handling nonce.

The only recovery I can find is to stop and restart the yate daemon.  I have not been able to find any trigger for this and in fact, it can run for hours to days without issue.  But when it fails, it never recovers without intervention.

Additional details.  Each instance of Yate has two registrations to DID Logic (one is for domestic calls, the other International).  Both fail at the same time however do not fail on the other SBC at the same time.  The issue is also evident when only a single registration on a single instance of Yate is used (ie, it's not related to conflict between sessions).  The issue and recovery is the same on version 5.4.0 and 5.5.1.

Where and how do I begin to diagnose this please?

Regards,
Graham


2017-09-07_06:28:54.008123 <sip:INFO> 'udp:0.0.0.0:5060' sending 'REGISTER sip:sip.au.didlogic.net:5060' 0x7f0a60007950 to 119.9.12.222:5060 [0x21d3d70]
------
REGISTER sip:sip.au.didlogic.net:5060 SIP/2.0
Contact: "xxxxx to sip.au.didlogic.net" <sip:xxxxx@103.233.yyy.yy:5060>
Expires: 600
To: <sip:xxxxx@sip.didlogic.net>
Call-ID: 173221880@sip.didlogic.net
Via: SIP/2.0/UDP 103.233.yyy.yy:5060;rport;branch=z9hG4bK247176001
From: "xxxxx to sip.au.didlogic.net" <sip:xxxxx@sip.didlogic.net>;tag=1875382347
CSeq: 155 REGISTER
User-Agent: YATE/5.5.1
Max-Forwards: 70
Allow: ACK, INVITE, BYE, CANCEL, REGISTER, REFER, OPTIONS, INFO
Content-Length: 0
------
SIP/2.0 401 Unauthorized
To: <sip:xxxxx@sip.didlogic.net>;tag=b27e1a1d33761e85846fc98f5f3a7e58.4889
Call-ID: 173221880@sip.didlogic.net
Via: SIP/2.0/UDP 103.233.yyy.yy:5060;rport=5060;branch=z9hG4bK247176001;received=103.233.yyy.yy
From: "xxxxx to sip.au.didlogic.net" <sip:xxxxx@sip.didlogic.net>;tag=1875382347
CSeq: 155 REGISTER
WWW-Authenticate: Digest realm="sip.didlogic.net", nonce="WbBbslmwWobEtIzCDtJooKG5bWSTpUPa3qzVIYA=", qop="auth"
Content-Length: 0
------
REGISTER sip:sip.au.didlogic.net:5060 SIP/2.0
Contact: "xxxxx to sip.au.didlogic.net" <sip:xxxxx@103.233.yyy.yy:5060>
Expires: 600
To: <sip:xxxxx@sip.didlogic.net>
Call-ID: 173221880@sip.didlogic.net
Via: SIP/2.0/UDP 103.233.yyy.yy:5060;rport;branch=z9hG4bK1969978764
From: "xxxxx to sip.au.didlogic.net" <sip:xxxxx@sip.didlogic.net>;tag=1875382347
User-Agent: YATE/5.5.1
Max-Forwards: 70
Allow: ACK, INVITE, BYE, CANCEL, REGISTER, REFER, OPTIONS, INFO
CSeq: 156 REGISTER
Authorization: Digest username="xxxxx", realm="sip.didlogic.net", nonce="WbBbslmwWobEtIzCDtJooKG5bWSTpUPa3qzVIYA=", uri="sip:sip.au.didlogic.net:5060", response="25751cd4d4cff6be877d7609fbc027f3", algorithm=MD5, qop=auth, nc=0000009c, cnonce="1e0fa4702bd9fa79d51f9c91f4be1dd8"
Content-Length: 0
------
SIP/2.0 200 OK
To: <sip:xxxxx@sip.didlogic.net>;tag=b27e1a1d33761e85846fc98f5f3a7e58.0b57
Call-ID: 173221880@sip.didlogic.net
Via: SIP/2.0/UDP 103.233.yyy.yy:5060;rport=5060;branch=z9hG4bK1969978764;received=103.233.yyy.yy
From: "xxxxx to sip.au.didlogic.net" <sip:xxxxx@sip.didlogic.net>;tag=1875382347
CSeq: 156 REGISTER
Contact: <sip:xxxxx@103.233.yyy.yy:5060>;expires=600
Content-Length: 0
------
2017-09-07_06:28:54.153073 <sip:CALL> SIP line 'didlogic-au' logon success to 119.9.12.222:5060

[Time passes - calls flow normally]

------
SIP/2.0 401 Unauthorized
To: <sip:xxxxx@sip.didlogic.net>;tag=b27e1a1d33761e85846fc98f5f3a7e58.8503
Call-ID: 173221880@sip.didlogic.net
Via: SIP/2.0/UDP 103.233.yyy.yy:5060;rport=5060;branch=z9hG4bK1561434704;received=103.233.yyy.yy
From: "xxxxx to sip.au.didlogic.net" <sip:xxxxx@sip.didlogic.net>;tag=521812222
CSeq: 218 REGISTER
WWW-Authenticate: Digest realm="sip.didlogic.net", nonce="WbCST1mwkSNWre0SwUZarFKx2E+PTcdh4A0WA4A=", qop="auth"
Content-Length: 0

------
2017-09-07_10:21:55.126349 <sip:WARN> SIP line 'didlogic-au' logon failure 401: Unauthorized

[marian]

Can you post the log before last 401 (full REGISTER transaction)?
Can you say what is wrong with nonce handling?

[Graham_M]

I'm unsure there is any issue with nonce.  When I raised the issue to DID Logic, their response was:

"Hello, when you try a standalone softphone with those same credentials, such as X-lite as in the screen grab below, does it still fail to authenticate? If it does then this is linked to the way yate calculates nonce and can't be troubleshooted on our end".

This is the only reason I mention nonce.

Below is the full log of the last call prior to the auth failure starting, followed by the full register log.

------
2017-09-07_10:20:56.102100 <sipengine:NOTE> Received non-branch ACK to non-2xx response! (sender bug)
2017-09-07_10:20:56.104163 <sip:INFO> 'udp:0.0.0.0:5060' received 949 bytes SIP message from 119.9.12.222:5060 [0x21d3d70]
------
INVITE sip:0700001234@103.233.yyy.yy:5060 SIP/2.0
Via: SIP/2.0/UDP 119.9.12.222;branch=z9hG4bK7321.347637a78087ecff3dbc4718e8a6e089.0
Via: SIP/2.0/UDP 101.0.yyy.yy:5080;received=101.0.yyy.yy;branch=z9hG4bK652f7b1c;rport=5080
Max-Forwards: 69
From: <sip:61711112468@sip.didlogic.net>;tag=as66a9302f
To: "0700001234" <sip:0700001234@103.233.yyy.yy>;tag=650186121
Contact: <sip:61711112468@101.0.yyy.yy:5080>
Call-ID: 17295278@103.233.yyy.yy
CSeq: 103 INVITE
User-Agent: DID Logic MGW
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces
Content-Type: application/sdp
Content-Length: 302

v=0
o=didlogic 2035236119 2035236122 IN IP4 101.0.yyy.yy
s=DID Logic MGW
c=IN IP4 101.0.yyy.yy
t=0 0
m=audio 12798 RTP/AVP 0 8 9 3 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
------
2017-09-07_10:20:56.113782 <sip:INFO> 'udp:0.0.0.0:5060' sending code 100 0x7f0a64009fa0 to 119.9.12.222:5060 [0x21d3d70]
------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 119.9.12.222;branch=z9hG4bK7321.347637a78087ecff3dbc4718e8a6e089.0;received=119.9.12.222
Via: SIP/2.0/UDP 101.0.yyy.yy:5080;received=101.0.yyy.yy;branch=z9hG4bK652f7b1c;rport=5080
From: <sip:61711112468@sip.didlogic.net>;tag=as66a9302f
To: "0700001234" <sip:0700001234@103.233.yyy.yy>;tag=650186121
Call-ID: 17295278@103.233.yyy.yy
CSeq: 103 INVITE
Server: YATE/5.5.1
Content-Length: 0

------
2017-09-07_10:20:56.114057 <sip:WARN> Got re-INVITE for missing dialog
2017-09-07_10:20:56.114330 <sip:INFO> 'udp:0.0.0.0:5060' sending code 481 0x7f0a640111c0 to 119.9.12.222:5060 [0x21d3d70]
------
SIP/2.0 481 Call/Transaction Does Not Exist
Via: SIP/2.0/UDP 119.9.12.222;branch=z9hG4bK7321.347637a78087ecff3dbc4718e8a6e089.0;received=119.9.12.222
Via: SIP/2.0/UDP 101.0.yyy.yy:5080;received=101.0.yyy.yy;branch=z9hG4bK652f7b1c;rport=5080
From: <sip:61711112468@sip.didlogic.net>;tag=as66a9302f
To: "0700001234" <sip:0700001234@103.233.yyy.yy>;tag=650186121
Call-ID: 17295278@103.233.yyy.yy
CSeq: 103 INVITE
Server: YATE/5.5.1
Contact: <sip:0700001234@103.233.yyy.yy:5060>
Allow: ACK, INVITE, BYE, CANCEL, REGISTER, REFER, OPTIONS, INFO
Content-Length: 0

------
2017-09-07_10:20:56.115401 <sip:INFO> 'udp:0.0.0.0:5060' received 419 bytes SIP message from 119.9.12.222:5060 [0x21d3d70]
------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 103.233.yyy.yy:5060;received=103.233.yyy.yy;rport=5060;branch=z9hG4bK1772598879
From: <sip:0700001234@103.233.yyy.yy>;tag=650186121
To: <sip:61711112468@sip.didlogic.net>;tag=as66a9302f
Call-ID: 17295278@103.233.yyy.yy
CSeq: 108 BYE
Server: DID Logic MGW
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces
Content-Length: 0

------
2017-09-07_10:20:56.131055 <sip:INFO> 'udp:0.0.0.0:5060' received 342 bytes SIP message from 119.9.12.222:5060 [0x21d3d70]
------
ACK sip:0700001234@103.233.yyy.yy:5060 SIP/2.0
Via: SIP/2.0/UDP 119.9.12.222;branch=z9hG4bK7321.347637a78087ecff3dbc4718e8a6e089.0
Max-Forwards: 69
From: <sip:61711112468@sip.didlogic.net>;tag=as66a9302f
To: "0700001234" <sip:0700001234@103.233.yyy.yy>;tag=650186121
Call-ID: 17295278@103.233.yyy.yy
CSeq: 103 ACK
Content-Length: 0





2017-09-07_10:21:55.005944 <sip:INFO> 'udp:0.0.0.0:5060' sending 'REGISTER sip:sip.au.didlogic.net:5060' 0x7f0a600050c0 to 119.9.12.222:5060 [0x21d3d70]
------
REGISTER sip:sip.au.didlogic.net:5060 SIP/2.0
Contact: "xxxxx to sip.au.didlogic.net" <sip:xxxxx@103.233.yyy.yy:5060>
Expires: 600
To: <sip:xxxxx@sip.didlogic.net>
Call-ID: 173221880@sip.didlogic.net
Via: SIP/2.0/UDP 103.233.yyy.yy:5060;rport;branch=z9hG4bK29905765
From: "xxxxx to sip.au.didlogic.net" <sip:xxxxx@sip.didlogic.net>;tag=521812222
CSeq: 217 REGISTER
User-Agent: YATE/5.5.1
Max-Forwards: 70
Allow: ACK, INVITE, BYE, CANCEL, REGISTER, REFER, OPTIONS, INFO
Content-Length: 0

2017-09-07_10:21:55.064410 <sip:INFO> 'udp:0.0.0.0:5060' received 470 bytes SIP message from 119.9.12.222:5060 [0x21d3d70]
------
SIP/2.0 401 Unauthorized
To: <sip:xxxxx@sip.didlogic.net>;tag=b27e1a1d33761e85846fc98f5f3a7e58.49ed
Call-ID: 173221880@sip.didlogic.net
Via: SIP/2.0/UDP 103.233.yyy.yy:5060;rport=5060;branch=z9hG4bK29905765;received=103.233.yyy.yy
From: "xxxxx to sip.au.didlogic.net" <sip:xxxxx@sip.didlogic.net>;tag=521812222
CSeq: 217 REGISTER
WWW-Authenticate: Digest realm="sip.didlogic.net", nonce="WbCST1mwkSN89fm4B9ocQDZ8zP3ckFlF4A0UAYA=", qop="auth"
Content-Length: 0

------
2017-09-07_10:21:55.065151 <sip:INFO> 'udp:0.0.0.0:5060' sending 'REGISTER sip:sip.au.didlogic.net:5060' 0x7f0a6800e0f0 to 119.9.12.222:5060 [0x21d3d70]
------
REGISTER sip:sip.au.didlogic.net:5060 SIP/2.0
Contact: "xxxxx to sip.au.didlogic.net" <sip:xxxxx@103.233.yyy.yy:5060>
Expires: 600
To: <sip:xxxxx@sip.didlogic.net>
Call-ID: 173221880@sip.didlogic.net
Via: SIP/2.0/UDP 103.233.yyy.yy:5060;rport;branch=z9hG4bK1561434704
From: "xxxxx to sip.au.didlogic.net" <sip:xxxxx@sip.didlogic.net>;tag=521812222
User-Agent: YATE/5.5.1
Max-Forwards: 70
Allow: ACK, INVITE, BYE, CANCEL, REGISTER, REFER, OPTIONS, INFO
CSeq: 218 REGISTER
Authorization: Digest username="xxxxx", realm="sip.didlogic.net", nonce="WbCST1mwkSN89fm4B9ocQDZ8zP3ckFlF4A0UAYA=", uri="sip:sip.au.didlogic.net:5060", response="525a10d95e82b87d7720496cd091688b", algorithm=MD5, qop=auth, nc=00000100, cnonce="18e5f3495bc2408c04cf087432d4118b"
Content-Length: 0

------
2017-09-07_10:21:55.122894 <sip:INFO> 'udp:0.0.0.0:5060' received 472 bytes SIP message from 119.9.12.222:5060 [0x21d3d70]
------
SIP/2.0 401 Unauthorized
To: <sip:xxxxx@sip.didlogic.net>;tag=b27e1a1d33761e85846fc98f5f3a7e58.8503
Call-ID: 173221880@sip.didlogic.net
Via: SIP/2.0/UDP 103.233.yyy.yy:5060;rport=5060;branch=z9hG4bK1561434704;received=103.233.yyy.yy
From: "xxxxx to sip.au.didlogic.net" <sip:xxxxx@sip.didlogic.net>;tag=521812222
CSeq: 218 REGISTER
WWW-Authenticate: Digest realm="sip.didlogic.net", nonce="WbCST1mwkSNWre0SwUZarFKx2E+PTcdh4A0WA4A=", qop="auth"
Content-Length: 0

------
2017-09-07_10:21:55.126349 <sip:WARN> SIP line 'didlogic-au' logon failure 401: Unauthorized

[marian]

Don't know what to say.
Did you tried another SIP client (X-lite) as suggested by provider? If it doesn't work this will definitely indicate a server failure.

You may also take a look at RFC 2617.
For 'qop'='auth' the response is calculated by:
response = md5(md5(username:realm:password):nonce:nc:cnonce:qop:md5(method:uri))
You may check Yate's response using log data (fields in Authorization header) and known password

You may also check (and dump here if possible) failed REGISTER transactions.
You may check for differences or patterns.

[Graham_M]

Yes.  I had Zoiper from memory at the time - it registered immediately, even while Yate was still failing.  But Yate was also registering successfully to another upstream at the same time without issue.  Very confusing.

Doing a reload from rmanager seems to trigger the problem (I think) but it occurs without any interaction as well. I'll have all the production traffic off one of the SBCs tomorrow so will have more of a play when I can break things without impact.

Thanks for your suggestions.  I will try checking the field values before and after failure.

[Graham_M]

Just a quick update here:  I have been able to reproduce the issue and with the help of SIP Digest Calculator (https://sourceforge.net/projects/sipdigetcalc), confirmed the Authorization header is correct as far as I can determine so I have referred the issue back to DID Logic for further investigation.

Thanks for your guidance on what to check.