External MWI subscribe succeeds, re-subscribe fails

Asterisk Asterisk Support
1

Hi all,

I have a strange issue getting asterisk 11.7.0 to get MWI from my voip provider (voip.ms). When I first start asterisk, the subscription works perfectly, but when it comes time to renew the subscription (after an hour), asterisk and my provider seem to get out of sync, and MWI stops working until I restart asterisk.

I did a SIP debug (below) and it appears to me that there are two problems. The first is that the provider is initially rejecting the re-registration (but accepting a second attempt). The second problem is that asterisk doesn’t appear to be recovering from the initial rejection properly.

<--- SIP read from UDP:96.44.149.186:5060 --->
NOTIFY sip:123456@192.168.1.2:5060 SIP/2.0
Via: SIP/2.0/UDP 96.44.149.186:5060;branch=z9hG4bK6491b7c2;rport
Max-Forwards: 70
Route: <sip:123456@192.168.1.2:5060>
From: "Unknown" <sip:Unknown@96.44.149.186>;tag=as62dd2194
To: <sip:123456@192.168.1.2:5060>;tag=as11dd826d
Contact: <sip:Unknown@96.44.149.186:5060>
Call-ID: 4cb907876212378a7a0aa64355a4de49@192.168.1.2:5060
CSeq: 136 NOTIFY
User-Agent: voip.ms
Event: message-summary
Content-Type: application/simple-message-summary
Subscription-State: active
Content-Length: 93

Messages-Waiting: no
Message-Account: sip:asterisk@96.44.149.186
Voice-Message: 0/0 (0/0)
<------------->
--- (14 headers 3 lines) ---

<--- Transmitting (no NAT) to 96.44.149.186:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 96.44.149.186:5060;branch=z9hG4bK6491b7c2;rport;received=96.44.149.186
From: "Unknown" <sip:Unknown@96.44.149.186>;tag=as62dd2194
To: <sip:123456@192.168.1.2:5060>;tag=as11dd826d
Call-ID: 4cb907876212378a7a0aa64355a4de49@192.168.1.2:5060
CSeq: 136 NOTIFY
Server: Asterisk PBX 11.7.0~dfsg-1~bpo70+1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Contact: <sip:123456@192.168.1.2:5060>
Content-Length: 0


<------------>
Reliably Transmitting (no NAT) to 96.44.149.186:5060:
SUBSCRIBE sip:123456@96.44.149.186:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.2:5060;branch=z9hG4bK3f00352b
Max-Forwards: 70
From: "asterisk" <sip:123456@192.168.1.2>;tag=as11dd826d
To: <sip:123456@losangeles.voip.ms>;tag=as62dd2194
Contact: <sip:123456@192.168.1.2:5060>
Call-ID: 4cb907876212378a7a0aa64355a4de49@192.168.1.2:5060
CSeq: 104 SUBSCRIBE
User-Agent: Asterisk PBX 11.7.0~dfsg-1~bpo70+1
Date: Sat, 01 Feb 2014 09:24:58 GMT
Event: message-summary
Accept: application/simple-message-summary
Expires: 3600
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0


---

<--- SIP read from UDP:96.44.149.186:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.1.2:5060;branch=z9hG4bK3f00352b;received=1.2.3.4;rport=5060
From: "asterisk" <sip:123456@192.168.1.2>;tag=as11dd826d
To: <sip:123456@losangeles.voip.ms>;tag=as62dd2194
Call-ID: 4cb907876212378a7a0aa64355a4de49@192.168.1.2:5060
CSeq: 104 SUBSCRIBE
Server: voip.ms
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="losangeles.voip.ms", nonce="4860662a"
Content-Length: 0

<------------->
--- (11 headers 0 lines) ---
Reliably Transmitting (no NAT) to 96.44.149.186:5060:
SUBSCRIBE sip:123456@96.44.149.186:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.2:5060;branch=z9hG4bK14626e68
Max-Forwards: 70
From: "asterisk" <sip:123456@192.168.1.2>;tag=as11dd826d
To: <sip:123456@losangeles.voip.ms>
Contact: <sip:123456@192.168.1.2:5060>
Call-ID: 4cb907876212378a7a0aa64355a4de49@192.168.1.2:5060
CSeq: 105 SUBSCRIBE
User-Agent: Asterisk PBX 11.7.0~dfsg-1~bpo70+1
Authorization: Digest username="123456", realm="losangeles.voip.ms", algorithm=MD5, uri="sip:123456@96.44.149.186:5060", nonce="4860662a", response="dcfd67426d7a28d34ce4d6d2c1f68b7c"
Date: Sat, 01 Feb 2014 09:24:58 GMT
Event: message-summary
Accept: application/simple-message-summary
Expires: 3600
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0


---

<--- SIP read from UDP:96.44.149.186:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.1.2:5060;branch=z9hG4bK14626e68;received=1.2.3.4;rport=5060
From: "asterisk" <sip:123456@192.168.1.2>;tag=as11dd826d
To: <sip:123456@losangeles.voip.ms>;tag=as12c73cbe
Call-ID: 4cb907876212378a7a0aa64355a4de49@192.168.1.2:5060
CSeq: 105 SUBSCRIBE
Server: voip.ms
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="losangeles.voip.ms", nonce="66e2acca"
Content-Length: 0

<------------->
--- (11 headers 0 lines) ---
Reliably Transmitting (no NAT) to 96.44.149.186:5060:
SUBSCRIBE sip:123456@96.44.149.186:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.2:5060;branch=z9hG4bK4ba29339
Max-Forwards: 70
From: "asterisk" <sip:123456@192.168.1.2>;tag=as11dd826d
To: <sip:123456@losangeles.voip.ms>
Contact: <sip:123456@192.168.1.2:5060>
Call-ID: 4cb907876212378a7a0aa64355a4de49@192.168.1.2:5060
CSeq: 106 SUBSCRIBE
User-Agent: Asterisk PBX 11.7.0~dfsg-1~bpo70+1
Authorization: Digest username="123456", realm="losangeles.voip.ms", algorithm=MD5, uri="sip:123456@96.44.149.186:5060", nonce="66e2acca", response="6be6bbd5774b338ed5c77becd7b5c9fa"
Date: Sat, 01 Feb 2014 09:24:58 GMT
Event: message-summary
Accept: application/simple-message-summary
Expires: 3600
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0


---

<--- SIP read from UDP:96.44.149.186:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.2:5060;branch=z9hG4bK4ba29339;received=1.2.3.4;rport=5060
From: "asterisk" <sip:123456@192.168.1.2>;tag=as11dd826d
To: <sip:123456@losangeles.voip.ms>;tag=as12c73cbe
Call-ID: 4cb907876212378a7a0aa64355a4de49@192.168.1.2:5060
CSeq: 106 SUBSCRIBE
Server: voip.ms
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Expires: 3600
Contact: <sip:123456@96.44.149.186:5060>;expires=3600
Content-Length: 0

<------------->
--- (12 headers 0 lines) ---

<--- SIP read from UDP:96.44.149.186:5060 --->
NOTIFY sip:123456@192.168.1.2:5060 SIP/2.0
Via: SIP/2.0/UDP 96.44.149.186:5060;branch=z9hG4bK68a0ce68;rport
Max-Forwards: 70
Route: <sip:123456@192.168.1.2:5060>
From: "Unknown" <sip:Unknown@96.44.149.186>;tag=as12c73cbe
To: <sip:123456@192.168.1.2:5060>;tag=as11dd826d
Contact: <sip:Unknown@96.44.149.186:5060>
Call-ID: 4cb907876212378a7a0aa64355a4de49@192.168.1.2:5060
CSeq: 102 NOTIFY
User-Agent: voip.ms
Event: message-summary
Content-Type: application/simple-message-summary
Subscription-State: active
Content-Length: 93

Messages-Waiting: no
Message-Account: sip:asterisk@96.44.149.186
Voice-Message: 0/0 (0/0)
<------------->
--- (14 headers 3 lines) ---

<--- Transmitting (no NAT) to 96.44.149.186:5060 --->
SIP/2.0 500 Server error
Via: SIP/2.0/UDP 96.44.149.186:5060;branch=z9hG4bK68a0ce68;rport;received=96.44.149.186
From: "Unknown" <sip:Unknown@96.44.149.186>;tag=as12c73cbe
To: <sip:123456@192.168.1.2:5060>;tag=as11dd826d
Call-ID: 4cb907876212378a7a0aa64355a4de49@192.168.1.2:5060
CSeq: 102 NOTIFY
Server: Asterisk PBX 11.7.0~dfsg-1~bpo70+1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0

Anybody got any ideas? I’ve already raised a ticket with the provider, but even if it is at fault in rejecting the initial resubscription, why is asterisk responding to subsequent NOTIFY messages with ‘500 Server Error’ given that the second subscription attempt was accepted?