Voicemail notification and MWI erratic behavior

BlazeStudios · December 28, 2018, 3:45pm

@Ollie Alright so this is what you should do so we can figure out what is actually happening.

SSH into the PBX and do yum install sngrep
From the system cli just run sngrep
When it loads you’re going to see a lot of things scrolling. Don’t worry, just hit F7 to open the Filter Options.
a) Use the down arrow key to get to the SIP To field, enter the extension of the PJSIP extension you’re having issues with.
b) Arrow down to the Message Types. Use the space bar to toggle (unset in this case) every option but NOTIFY.
c) Arrow down to the Filter option to highlight it and hit enter. This will now filter all the messages on the screen to show only NOTIFY’s that are destined for your PJSIP extension with issues.
Arrow down the list to choose a NOTIFY message, hit enter to view it and esc to go back to the list.

The Filter screen will look like this for you, will 100 as the SIP To in the example screenshot

sngrep_filterscreen

Once you are viewing the message you can see if the Event: is message-summary and look for the body of the message to see what information is there. Should look like this:

sngrep_eventbody

You can look to the left of the the NOTIFY message on that screen and you’ll see the call ladder like this:

sngrep_ladder

Note that I cut the IPs that would appear over those top lines. Left side is the PBX, right side is the device. You should see that for the message, a 200 OK that indicates the phone did get the message.

You’ll just have to filter and then look through the messages and you can do testing to see when the “good NOTIFY” goes out (ie the phone does show MWI lights) and when it goes “bad” (MWI doesn’t show at all, etc). You can compare each one and see if the message body changes, what changes and you can confirm that each NOTIFY sent got a 200 OK reply from the phone.

PJSIP and Chan_SIP do not do MWI the same way. This could be how the extension is setup for its MWI solicitation or something else. Blindly thinking that “It worked in Chan_SIP but not in PJSIP so PJSIP doesn’t work right” is wrong. They have different settings, they handle things slightly different than the other so when you do things under Chan_SIP and then PJSIP you may have to make some tweaks or adjustments.

Ollie · December 29, 2018, 8:25pm

Tom, thanks a ton for pointing me in the right direction and taking the time to write that lengthy reply. At the end of the day, I would prefer to stay with pjsip for reasons already mentioned in this thread and others.

So converted extension back to pjsip and rebooted. I decided to go ahead and grab syslogs from the phone and set a debug logging channel in asterisk with verbose and debug set at 5, along with pjsip logging.

09:48 rebooted phone (ext 701) - Here is sngrep output

2018/12/29 09:48:15.777137 192.168.0.35:5060 -> 192.168.0.137:5060
NOTIFY sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.35:5060;rport;branch=z9hG4bKPj783f1824-3df9-41eb-8e7f-afdac49ab95b
From: <sip:[email protected]>;tag=dba2cd6b-0fe0-4253-a6e0-b428a927493e
To: <sip:[email protected]>
Contact: <sip:[email protected]:5060>
Call-ID: 66d161d0-60f1-4e77-a1ce-13f191731d6d
CSeq: 57862 NOTIFY
Subscription-State: terminated
Event: message-summary
Allow-Events: presence, dialog, message-summary, refer
Max-Forwards: 70
User-Agent: FPBX-14.0.5.5(13.22.0)
Content-Type: application/simple-message-summary
Content-Length:    49

Messages-Waiting: yes
Voice-Message: 4/0 (0/0)


2018/12/29 09:48:15.931607 192.168.0.137:5060 -> 192.168.0.35:5060
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.35:5060;rport=5060;branch=z9hG4bKPj783f1824-3df9-41eb-8e7f-afdac49ab95b
From: <sip:[email protected]>;tag=dba2cd6b-0fe0-4253-a6e0-b428a927493e
To: <sip:[email protected]>;tag=2762033559
Call-ID: 66d161d0-60f1-4e77-a1ce-13f191731d6d
CSeq: 57862 NOTIFY
User-Agent: Yealink SIP-T29G 46.83.0.50
Content-Length: 0



2018/12/29 09:48:15.777905 192.168.0.35:5060 -> 192.168.0.137:5060
NOTIFY sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.35:5060;rport;branch=z9hG4bKPj1ab9ab2b-e30c-4362-9d06-d2fba14e2f6e
From: <sip:[email protected]>;tag=79062b52-3a13-4066-9165-8b1de59504d9
To: <sip:[email protected]>
Contact: <sip:[email protected]:5060>
Call-ID: 652674df-b85e-4008-9f94-7868410182d3
CSeq: 46361 NOTIFY
Subscription-State: terminated
Event: message-summary
Allow-Events: presence, dialog, message-summary, refer
Max-Forwards: 70
User-Agent: FPBX-14.0.5.5(13.22.0)
Content-Type: application/simple-message-summary
Content-Length:    49

Messages-Waiting: yes
Voice-Message: 4/0 (0/0)


2018/12/29 09:48:15.953689 192.168.0.137:5060 -> 192.168.0.35:5060
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.35:5060;rport=5060;branch=z9hG4bKPj1ab9ab2b-e30c-4362-9d06-d2fba14e2f6e
From: <sip:[email protected]>;tag=79062b52-3a13-4066-9165-8b1de59504d9
To: <sip:[email protected]>;tag=1448161403
Call-ID: 652674df-b85e-4008-9f94-7868410182d3
CSeq: 46361 NOTIFY
User-Agent: Yealink SIP-T29G 46.83.0.50
Content-Length: 0

At 10:38 lost MWI - sngrep output

2018/12/29 10:38:14.954535 192.168.0.35:5060 -> 192.168.0.137:5060
NOTIFY sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.35:5060;rport;branch=z9hG4bKPj8bc8380c-3cc7-4d6e-a7d8-4a558a47616b
From: <sip:[email protected]>;tag=8ada3409-76ee-40d9-a9b4-5f5583bc002a
To: <sip:[email protected]>
Contact: <sip:[email protected]:5060>
Call-ID: f6de6b17-8e9e-472d-9d6d-fa2d63d19fc6
CSeq: 45634 NOTIFY
Subscription-State: terminated
Event: message-summary
Allow-Events: presence, dialog, message-summary, refer
Max-Forwards: 70
User-Agent: FPBX-14.0.5.5(13.22.0)
Content-Type: application/simple-message-summary
Content-Length:    48

Messages-Waiting: no
Voice-Message: 0/0 (0/0)


2018/12/29 10:38:15.004899 192.168.0.137:5060 -> 192.168.0.35:5060
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.35:5060;rport=5060;branch=z9hG4bKPj8bc8380c-3cc7-4d6e-a7d8-4a558a47616b
From: <sip:[email protected]>;tag=8ada3409-76ee-40d9-a9b4-5f5583bc002a
To: <sip:[email protected]>;tag=3831891063
Call-ID: f6de6b17-8e9e-472d-9d6d-fa2d63d19fc6
CSeq: 45634 NOTIFY
User-Agent: Yealink SIP-T29G 46.83.0.50
Content-Length: 0

Here is a snip from asterisk debug log during 10:38. It appears that there is a NOTIFY with messages waiting, then another NOTIFY following that says there is not

[2018-12-29 10:38:14] DEBUG[26956] res_pjsip_pubsub.c: sub_tree 0x7fdc780783d0 sub_tree state Normal
[2018-12-29 10:38:14] DEBUG[26956] res_pjsip_pubsub.c: sub_tree 0x7fdc780783d0 sub_tree state Normal
[2018-12-29 10:38:14] DEBUG[26956] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 192.168.0.35:5060 (this may be re-written again later)
[2018-12-29 10:38:14] DEBUG[26956] netsock2.c: Splitting '192.168.0.137' into...
[2018-12-29 10:38:14] DEBUG[26956] netsock2.c: ...host '192.168.0.137' and port ''.
[2018-12-29 10:38:14] DEBUG[26956] res_pjsip_nat.c: Request is being sent to local address, skipping NAT manipulation
[2018-12-29 10:38:14] VERBOSE[26956] res_pjsip_logger.c: <--- Transmitting SIP request (648 bytes) to UDP:192.168.0.137:5060 --->
NOTIFY sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.35:5060;rport;branch=z9hG4bKPj6b9555e8-7580-49ed-a766-6713ecf7b444
From: <sip:[email protected]>;tag=882c44e4-6ff7-4e70-b6c0-ca78e22f66f7
To: "701" <sip:[email protected]>;tag=3963180513
Contact: <sip:192.168.0.35:5060>
Call-ID: [email protected]
CSeq: 21193 NOTIFY
Event: message-summary
Subscription-State: active;expires=3600
Allow-Events: presence, dialog, message-summary, refer
Max-Forwards: 70
User-Agent: FPBX-14.0.5.5(13.22.0)
Content-Type: application/simple-message-summary
Content-Length:    49

Messages-Waiting: yes
Voice-Message: 4/0 (0/0)

[2018-12-29 10:38:14] DEBUG[26956] res_pjsip_pubsub.c: evsub 0x7fdc78671dd8 state ACTIVE event USER sub_tree 0x7fdc780783d0 sub_tree state Normal
[2018-12-29 10:38:14] DEBUG[26956] res_pjsip_pubsub.c: Updating persistence for '701->701'  prune on boot: no
[2018-12-29 10:38:14] VERBOSE[2385] res_pjsip_logger.c: <--- Received SIP request (556 bytes) from UDP:192.168.0.137:5060 --->
REGISTER sip:192.168.0.35:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.137:5060;branch=z9hG4bK2198135894
From: "701" <sip:[email protected]:5060>;tag=4197363148
To: "701" <sip:[email protected]:5060>
Call-ID: [email protected]
CSeq: 3 REGISTER
Contact: <sip:[email protected]:5060>
Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE
Max-Forwards: 70
User-Agent: Yealink SIP-T29G 46.83.0.50
Expires: 3600
Allow-Events: talk,hold,conference,refer,check-sync
Content-Length: 0


[2018-12-29 10:38:14] DEBUG[2385] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=3 (rdata0x7fdc6c138f28)
[2018-12-29 10:38:14] DEBUG[2385] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000047 to use for Request msg REGISTER/cseq=3 (rdata0x7fdc6c138f28)
[2018-12-29 10:38:14] DEBUG[4736] netsock2.c: Splitting '192.168.0.137' into...
[2018-12-29 10:38:14] DEBUG[4736] netsock2.c: ...host '192.168.0.137' and port ''.
[2018-12-29 10:38:14] DEBUG[4736] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against
[2018-12-29 10:38:14] DEBUG[4736] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '701' domain '192.168.0.35'
[2018-12-29 10:38:14] DEBUG[4736] res_pjsip_endpoint_identifier_user.c: Identified by From username '701' domain '192.168.0.35'
[2018-12-29 10:38:14] DEBUG[4736] res_pjsip_authenticator_digest.c: Using default realm 'asterisk' on incoming auth '701-auth'.
[2018-12-29 10:38:14] DEBUG[4736] netsock2.c: Splitting '192.168.0.35' into...
[2018-12-29 10:38:14] DEBUG[4736] netsock2.c: ...host '192.168.0.35' and port ''.
[2018-12-29 10:38:14] DEBUG[4736] netsock2.c: Splitting '192.168.0.137' into...
[2018-12-29 10:38:14] DEBUG[4736] netsock2.c: ...host '192.168.0.137' and port ''.
[2018-12-29 10:38:14] DEBUG[4736] netsock2.c: Splitting '192.168.0.137' into...
[2018-12-29 10:38:14] DEBUG[4736] netsock2.c: ...host '192.168.0.137' and port ''.
[2018-12-29 10:38:14] DEBUG[4736] res_pjsip_nat.c: Request is being sent to local address, skipping NAT manipulation
[2018-12-29 10:38:14] VERBOSE[4736] res_pjsip_logger.c: <--- Transmitting SIP response (485 bytes) to UDP:192.168.0.137:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.0.137:5060;rport=5060;received=192.168.0.137;branch=z9hG4bK2198135894
Call-ID: [email protected]
From: "701" <sip:[email protected]>;tag=4197363148
To: "701" <sip:[email protected]>;tag=z9hG4bK2198135894
CSeq: 3 REGISTER
WWW-Authenticate: Digest  realm="asterisk",nonce="1546101494/e9ca919c625956740427ed22ab4e1993",opaque="558cac7324e6ed34",algorithm=md5,qop="auth"
Server: FPBX-14.0.5.5(13.22.0)
Content-Length:  0


[2018-12-29 10:38:14] DEBUG[19751] manager.c: Examining AMI event:
Event: ChallengeSent
Privilege: security,all
EventTV: 2018-12-29T10:38:14.851-0600
Severity: Informational
Service: PJSIP
EventVersion: 1
AccountID: 701
SessionID: [email protected]
LocalAddress: IPV4/UDP/192.168.0.35/5060
RemoteAddress: IPV4/UDP/192.168.0.137/5060
Challenge: 


[2018-12-29 10:38:14] VERBOSE[2385] res_pjsip_logger.c: <--- Received SIP response (394 bytes) from UDP:192.168.0.137:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.35:5060;rport=5060;branch=z9hG4bKPj6b9555e8-7580-49ed-a766-6713ecf7b444
From: <sip:[email protected]>;tag=882c44e4-6ff7-4e70-b6c0-ca78e22f66f7
To: "701" <sip:[email protected]>;tag=3963180513
Call-ID: [email protected]
CSeq: 21193 NOTIFY
Contact: <sip:[email protected]:5060>
User-Agent: Yealink SIP-T29G 46.83.0.50
Content-Length: 0


[2018-12-29 10:38:14] DEBUG[2385] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fdc5c011008 for Response msg 200/NOTIFY/cseq=21193 (rdata0x7fdc6c138f28)
[2018-12-29 10:38:14] DEBUG[2385] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000037 associated with dialog dlg0x7fdc5c011008
[2018-12-29 10:38:14] VERBOSE[2385] res_pjsip_logger.c: <--- Received SIP request (823 bytes) from UDP:192.168.0.137:5060 --->
REGISTER sip:192.168.0.35:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.137:5060;branch=z9hG4bK3164244746
From: "701" <sip:[email protected]:5060>;tag=4197363148
To: "701" <sip:[email protected]:5060>
Call-ID: [email protected]
CSeq: 4 REGISTER
Contact: <sip:[email protected]:5060>
Authorization: Digest username="701", realm="asterisk", nonce="1546101494/e9ca919c625956740427ed22ab4e1993", uri="sip:192.168.0.35:5060", response="70aff0a428c3ea13d553e406c84d67c0", algorithm=MD5, cnonce="0a4f113b", opaque="558cac7324e6ed34", qop=auth, nc=00000001
Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE
Max-Forwards: 70
User-Agent: Yealink SIP-T29G 46.83.0.50
Expires: 3600
Allow-Events: talk,hold,conference,refer,check-sync
Content-Length: 0


[2018-12-29 10:38:14] DEBUG[2385] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=4 (rdata0x7fdc6c138f28)
[2018-12-29 10:38:14] DEBUG[2385] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000047 to use for Request msg REGISTER/cseq=4 (rdata0x7fdc6c138f28)
[2018-12-29 10:38:14] DEBUG[25789] netsock2.c: Splitting '192.168.0.137' into...
[2018-12-29 10:38:14] DEBUG[25789] netsock2.c: ...host '192.168.0.137' and port ''.
[2018-12-29 10:38:14] DEBUG[25789] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against
[2018-12-29 10:38:14] DEBUG[25789] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '701' domain '192.168.0.35'
[2018-12-29 10:38:14] DEBUG[25789] res_pjsip_endpoint_identifier_user.c: Identified by From username '701' domain '192.168.0.35'
[2018-12-29 10:38:14] DEBUG[25789] res_pjsip_authenticator_digest.c: Using default realm 'asterisk' on incoming auth '701-auth'.
[2018-12-29 10:38:14] DEBUG[25789] res_pjsip_authenticator_digest.c: Calculated nonce 1546101494/e9ca919c625956740427ed22ab4e1993. Actual nonce is 1546101494/e9ca919c625956740427ed22ab4e1993
[2018-12-29 10:38:14] DEBUG[25789] netsock2.c: Splitting '192.168.0.35' into...
[2018-12-29 10:38:14] DEBUG[25789] netsock2.c: ...host '192.168.0.35' and port ''.
[2018-12-29 10:38:14] DEBUG[25789] netsock2.c: Splitting '192.168.0.137' into...
[2018-12-29 10:38:14] DEBUG[25789] netsock2.c: ...host '192.168.0.137' and port ''.
[2018-12-29 10:38:14] DEBUG[25789] res_pjsip_registrar.c: Matched id '701' to aor '701'
[2018-12-29 10:38:14] DEBUG[25789] res_pjsip_registrar.c: Matched aor '701' by To username
[2018-12-29 10:38:14] DEBUG[25789] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0)
[2018-12-29 10:38:14] DEBUG[25789] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[2018-12-29 10:38:14] DEBUG[25789] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0)
[2018-12-29 10:38:14] DEBUG[25789] config.c: extract uint from [5060] in [0, 4294967295] gives [5060](0)
[2018-12-29 10:38:14] DEBUG[25789] config.c: extract uint from [60] in [0, 86400] gives [60](0)
[2018-12-29 10:38:14] DEBUG[25789] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0)
[2018-12-29 10:38:14] DEBUG[25789] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[2018-12-29 10:38:14] DEBUG[25789] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0)
[2018-12-29 10:38:14] DEBUG[25789] config.c: extract uint from [5060] in [0, 4294967295] gives [5060](0)
[2018-12-29 10:38:14] DEBUG[25789] config.c: extract uint from [60] in [0, 86400] gives [60](0)
[2018-12-29 10:38:14] DEBUG[25789] res_pjsip_registrar.c: Refreshed contact 'sip:[email protected]:5060' on AOR '701' with new expiration of 3600 seconds
[2018-12-29 10:38:14] DEBUG[25789] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0)
[2018-12-29 10:38:14] DEBUG[25789] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[2018-12-29 10:38:14] DEBUG[25789] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0)
[2018-12-29 10:38:14] DEBUG[25789] config.c: extract uint from [5060] in [0, 4294967295] gives [5060](0)
[2018-12-29 10:38:14] DEBUG[25789] config.c: extract uint from [60] in [0, 86400] gives [60](0)
[2018-12-29 10:38:14] DEBUG[25789] netsock2.c: Splitting '192.168.0.137' into...
[2018-12-29 10:38:14] DEBUG[25789] netsock2.c: ...host '192.168.0.137' and port ''.
[2018-12-29 10:38:14] DEBUG[25789] res_pjsip_nat.c: Request is being sent to local address, skipping NAT manipulation
[2018-12-29 10:38:14] VERBOSE[25789] res_pjsip_logger.c: <--- Transmitting SIP response (432 bytes) to UDP:192.168.0.137:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.137:5060;rport=5060;received=192.168.0.137;branch=z9hG4bK3164244746
Call-ID: [email protected]
From: "701" <sip:[email protected]>;tag=4197363148
To: "701" <sip:[email protected]>;tag=z9hG4bK3164244746
CSeq: 4 REGISTER
Date: Sat, 29 Dec 2018 16:38:14 GMT
Contact: <sip:[email protected]:5060>;expires=3599
Expires: 3600
Server: FPBX-14.0.5.5(13.22.0)
Content-Length:  0


[2018-12-29 10:38:14] DEBUG[2270] threadpool.c: Increasing threadpool Sorcery's size by 1
[2018-12-29 10:38:14] DEBUG[19751] manager.c: Examining AMI event:
Event: SuccessfulAuth
Privilege: security,all
EventTV: 2018-12-29T10:38:14.950-0600
Severity: Informational
Service: PJSIP
EventVersion: 1
AccountID: 701
SessionID: [email protected]
LocalAddress: IPV4/UDP/192.168.0.35/5060
RemoteAddress: IPV4/UDP/192.168.0.137/5060
UsingPassword: 1


[2018-12-29 10:38:14] DEBUG[17585] res_pjsip_mwi.c: Sending unsolicited MWI NOTIFY to endpoint 701, new messages: 0, old messages: 0
[2018-12-29 10:38:14] DEBUG[17585] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0)
[2018-12-29 10:38:14] DEBUG[17585] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[2018-12-29 10:38:14] DEBUG[17585] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0)
[2018-12-29 10:38:14] DEBUG[17585] config.c: extract uint from [5060] in [0, 4294967295] gives [5060](0)
[2018-12-29 10:38:14] DEBUG[17585] config.c: extract uint from [60] in [0, 86400] gives [60](0)
[2018-12-29 10:38:14] DEBUG[17585] res_pjsip.c: 0x2da3a70: Wrapper created
[2018-12-29 10:38:14] DEBUG[17585] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 192.168.0.35:5060 (this may be re-written again later)
[2018-12-29 10:38:14] DEBUG[17585] netsock2.c: Splitting '192.168.0.137' into...
[2018-12-29 10:38:14] DEBUG[17585] netsock2.c: ...host '192.168.0.137' and port ''.
[2018-12-29 10:38:14] DEBUG[17585] res_pjsip_nat.c: Request is being sent to local address, skipping NAT manipulation
[2018-12-29 10:38:14] VERBOSE[17585] res_pjsip_logger.c: <--- Transmitting SIP request (632 bytes) to UDP:192.168.0.137:5060 --->
NOTIFY sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.35:5060;rport;branch=z9hG4bKPj8bc8380c-3cc7-4d6e-a7d8-4a558a47616b
From: <sip:[email protected]>;tag=8ada3409-76ee-40d9-a9b4-5f5583bc002a
To: <sip:[email protected]>
Contact: <sip:[email protected]:5060>
Call-ID: f6de6b17-8e9e-472d-9d6d-fa2d63d19fc6
CSeq: 45634 NOTIFY
Subscription-State: terminated
Event: message-summary
Allow-Events: presence, dialog, message-summary, refer
Max-Forwards: 70
User-Agent: FPBX-14.0.5.5(13.22.0)
Content-Type: application/simple-message-summary
Content-Length:    48

Messages-Waiting: no
Voice-Message: 0/0 (0/0)

Ollie · December 29, 2018, 8:28pm

At 11:28 phone give tone stutter that there is MWI but then immediately turns off.

Here is sngrep output

2018/12/29 11:28:14.994516 192.168.0.35:5060 -> 192.168.0.137:5060
NOTIFY sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.35:5060;rport;branch=z9hG4bKPj78193837-cb5f-4fbd-94c1-5d94b8372626
From: <sip:[email protected]>;tag=1723ae2c-116b-448a-bca9-2a9067a0e3a5
To: <sip:[email protected]>
Contact: <sip:[email protected]:5060>
Call-ID: 7a5dac9a-dfa8-4626-85f2-a11308ff7af1
CSeq: 28643 NOTIFY
Subscription-State: terminated
Event: message-summary
Allow-Events: presence, dialog, message-summary, refer
Max-Forwards: 70
User-Agent: FPBX-14.0.5.5(13.22.0)
Content-Type: application/simple-message-summary
Content-Length:    48

Messages-Waiting: no
Voice-Message: 0/0 (0/0)


2018/12/29 11:28:15.063019 192.168.0.137:5060 -> 192.168.0.35:5060
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.35:5060;rport=5060;branch=z9hG4bKPj78193837-cb5f-4fbd-94c1-5d94b8372626
From: <sip:[email protected]>;tag=1723ae2c-116b-448a-bca9-2a9067a0e3a5
To: <sip:[email protected]>;tag=3123329425
Call-ID: 7a5dac9a-dfa8-4626-85f2-a11308ff7af1
CSeq: 28643 NOTIFY
User-Agent: Yealink SIP-T29G 46.83.0.50
Content-Length: 0

Here is the asterisk debug during this same time. Again we have a NOTIFY with msgs then a NOTIFY immediately following saying there is not.

[2018-12-29 11:28:14] DEBUG[17585] res_pjsip_pubsub.c: sub_tree 0x7fdc780783d0 sub_tree state Normal
[2018-12-29 11:28:14] DEBUG[17585] res_pjsip_pubsub.c: sub_tree 0x7fdc780783d0 sub_tree state Normal
[2018-12-29 11:28:14] DEBUG[17585] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 192.168.0.35:5060 (this may be re-written again later)
[2018-12-29 11:28:14] DEBUG[17585] netsock2.c: Splitting '192.168.0.137' into...
[2018-12-29 11:28:14] DEBUG[17585] netsock2.c: ...host '192.168.0.137' and port ''.
[2018-12-29 11:28:14] DEBUG[17585] res_pjsip_nat.c: Request is being sent to local address, skipping NAT manipulation
[2018-12-29 11:28:14] VERBOSE[17585] res_pjsip_logger.c: <--- Transmitting SIP request (648 bytes) to UDP:192.168.0.137:5060 --->
NOTIFY sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.35:5060;rport;branch=z9hG4bKPj29dfd21d-b215-4f63-8ead-2ec3195f21b6
From: <sip:[email protected]>;tag=882c44e4-6ff7-4e70-b6c0-ca78e22f66f7
To: "701" <sip:[email protected]>;tag=3963180513
Contact: <sip:192.168.0.35:5060>
Call-ID: [email protected]
CSeq: 21194 NOTIFY
Event: message-summary
Subscription-State: active;expires=3599
Allow-Events: presence, dialog, message-summary, refer
Max-Forwards: 70
User-Agent: FPBX-14.0.5.5(13.22.0)
Content-Type: application/simple-message-summary
Content-Length:    49

Messages-Waiting: yes
Voice-Message: 4/0 (0/0)

[2018-12-29 11:28:14] DEBUG[17585] res_pjsip_pubsub.c: evsub 0x7fdc78671dd8 state ACTIVE event USER sub_tree 0x7fdc780783d0 sub_tree state Normal
[2018-12-29 11:28:14] DEBUG[17585] res_pjsip_pubsub.c: Updating persistence for '701->701'  prune on boot: no
[2018-12-29 11:28:14] VERBOSE[2385] res_pjsip_logger.c: <--- Received SIP request (555 bytes) from UDP:192.168.0.137:5060 --->
REGISTER sip:192.168.0.35:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.137:5060;branch=z9hG4bK659643445
From: "701" <sip:[email protected]:5060>;tag=4197363148
To: "701" <sip:[email protected]:5060>
Call-ID: [email protected]
CSeq: 5 REGISTER
Contact: <sip:[email protected]:5060>
Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE
Max-Forwards: 70
User-Agent: Yealink SIP-T29G 46.83.0.50
Expires: 3600
Allow-Events: talk,hold,conference,refer,check-sync
Content-Length: 0


[2018-12-29 11:28:14] DEBUG[2385] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=5 (rdata0x7fdc6c138f28)
[2018-12-29 11:28:14] DEBUG[2385] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000047 to use for Request msg REGISTER/cseq=5 (rdata0x7fdc6c138f28)
[2018-12-29 11:28:14] DEBUG[4736] netsock2.c: Splitting '192.168.0.137' into...
[2018-12-29 11:28:14] DEBUG[4736] netsock2.c: ...host '192.168.0.137' and port ''.
[2018-12-29 11:28:14] DEBUG[4736] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against
[2018-12-29 11:28:14] DEBUG[4736] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '701' domain '192.168.0.35'
[2018-12-29 11:28:14] DEBUG[4736] res_pjsip_endpoint_identifier_user.c: Identified by From username '701' domain '192.168.0.35'
[2018-12-29 11:28:14] DEBUG[4736] res_pjsip_authenticator_digest.c: Using default realm 'asterisk' on incoming auth '701-auth'.
[2018-12-29 11:28:14] DEBUG[4736] netsock2.c: Splitting '192.168.0.35' into...
[2018-12-29 11:28:14] DEBUG[4736] netsock2.c: ...host '192.168.0.35' and port ''.
[2018-12-29 11:28:14] DEBUG[4736] netsock2.c: Splitting '192.168.0.137' into...
[2018-12-29 11:28:14] DEBUG[4736] netsock2.c: ...host '192.168.0.137' and port ''.
[2018-12-29 11:28:14] DEBUG[4736] netsock2.c: Splitting '192.168.0.137' into...
[2018-12-29 11:28:14] DEBUG[4736] netsock2.c: ...host '192.168.0.137' and port ''.
[2018-12-29 11:28:14] DEBUG[4736] res_pjsip_nat.c: Request is being sent to local address, skipping NAT manipulation
[2018-12-29 11:28:14] VERBOSE[4736] res_pjsip_logger.c: <--- Transmitting SIP response (483 bytes) to UDP:192.168.0.137:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.0.137:5060;rport=5060;received=192.168.0.137;branch=z9hG4bK659643445
Call-ID: [email protected]
From: "701" <sip:[email protected]>;tag=4197363148
To: "701" <sip:[email protected]>;tag=z9hG4bK659643445
CSeq: 5 REGISTER
WWW-Authenticate: Digest  realm="asterisk",nonce="1546104494/f3bb7941db7ce902f107eb1f5ed19785",opaque="53540a191f5e5033",algorithm=md5,qop="auth"
Server: FPBX-14.0.5.5(13.22.0)
Content-Length:  0


[2018-12-29 11:28:14] DEBUG[19751] manager.c: Examining AMI event:
Event: ChallengeSent
Privilege: security,all
EventTV: 2018-12-29T11:28:14.837-0600
Severity: Informational
Service: PJSIP
EventVersion: 1
AccountID: 701
SessionID: [email protected]
LocalAddress: IPV4/UDP/192.168.0.35/5060
RemoteAddress: IPV4/UDP/192.168.0.137/5060
Challenge: 


[2018-12-29 11:28:14] VERBOSE[2385] res_pjsip_logger.c: <--- Received SIP response (394 bytes) from UDP:192.168.0.137:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.35:5060;rport=5060;branch=z9hG4bKPj29dfd21d-b215-4f63-8ead-2ec3195f21b6
From: <sip:[email protected]>;tag=882c44e4-6ff7-4e70-b6c0-ca78e22f66f7
To: "701" <sip:[email protected]>;tag=3963180513
Call-ID: [email protected]
CSeq: 21194 NOTIFY
Contact: <sip:[email protected]:5060>
User-Agent: Yealink SIP-T29G 46.83.0.50
Content-Length: 0


[2018-12-29 11:28:14] DEBUG[2385] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fdc5c011008 for Response msg 200/NOTIFY/cseq=21194 (rdata0x7fdc6c138f28)
[2018-12-29 11:28:14] DEBUG[2385] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000037 associated with dialog dlg0x7fdc5c011008
[2018-12-29 11:28:14] VERBOSE[2385] res_pjsip_logger.c: <--- Received SIP request (823 bytes) from UDP:192.168.0.137:5060 --->
REGISTER sip:192.168.0.35:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.137:5060;branch=z9hG4bK3289336715
From: "701" <sip:[email protected]:5060>;tag=4197363148
To: "701" <sip:[email protected]:5060>
Call-ID: [email protected]
CSeq: 6 REGISTER
Contact: <sip:[email protected]:5060>
Authorization: Digest username="701", realm="asterisk", nonce="1546104494/f3bb7941db7ce902f107eb1f5ed19785", uri="sip:192.168.0.35:5060", response="0bf8390731a2d3488c1aa045c8a20d12", algorithm=MD5, cnonce="0a4f113b", opaque="53540a191f5e5033", qop=auth, nc=00000001
Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE
Max-Forwards: 70
User-Agent: Yealink SIP-T29G 46.83.0.50
Expires: 3600
Allow-Events: talk,hold,conference,refer,check-sync
Content-Length: 0


[2018-12-29 11:28:14] DEBUG[2385] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=6 (rdata0x7fdc6c138f28)
[2018-12-29 11:28:14] DEBUG[2385] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000047 to use for Request msg REGISTER/cseq=6 (rdata0x7fdc6c138f28)
[2018-12-29 11:28:14] DEBUG[14333] netsock2.c: Splitting '192.168.0.137' into...
[2018-12-29 11:28:14] DEBUG[14333] netsock2.c: ...host '192.168.0.137' and port ''.
[2018-12-29 11:28:14] DEBUG[14333] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against
[2018-12-29 11:28:14] DEBUG[14333] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '701' domain '192.168.0.35'
[2018-12-29 11:28:14] DEBUG[14333] res_pjsip_endpoint_identifier_user.c: Identified by From username '701' domain '192.168.0.35'
[2018-12-29 11:28:14] DEBUG[14333] res_pjsip_authenticator_digest.c: Using default realm 'asterisk' on incoming auth '701-auth'.
[2018-12-29 11:28:14] DEBUG[14333] res_pjsip_authenticator_digest.c: Calculated nonce 1546104494/f3bb7941db7ce902f107eb1f5ed19785. Actual nonce is 1546104494/f3bb7941db7ce902f107eb1f5ed19785
[2018-12-29 11:28:14] DEBUG[14333] netsock2.c: Splitting '192.168.0.35' into...
[2018-12-29 11:28:14] DEBUG[14333] netsock2.c: ...host '192.168.0.35' and port ''.
[2018-12-29 11:28:14] DEBUG[14333] netsock2.c: Splitting '192.168.0.137' into...
[2018-12-29 11:28:14] DEBUG[14333] netsock2.c: ...host '192.168.0.137' and port ''.
[2018-12-29 11:28:14] DEBUG[14333] res_pjsip_registrar.c: Matched id '701' to aor '701'
[2018-12-29 11:28:14] DEBUG[14333] res_pjsip_registrar.c: Matched aor '701' by To username
[2018-12-29 11:28:14] DEBUG[14333] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0)
[2018-12-29 11:28:14] DEBUG[14333] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[2018-12-29 11:28:14] DEBUG[14333] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0)
[2018-12-29 11:28:14] DEBUG[14333] config.c: extract uint from [5060] in [0, 4294967295] gives [5060](0)
[2018-12-29 11:28:14] DEBUG[14333] config.c: extract uint from [60] in [0, 86400] gives [60](0)
[2018-12-29 11:28:14] DEBUG[14333] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0)
[2018-12-29 11:28:14] DEBUG[14333] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[2018-12-29 11:28:14] DEBUG[14333] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0)
[2018-12-29 11:28:14] DEBUG[14333] config.c: extract uint from [5060] in [0, 4294967295] gives [5060](0)
[2018-12-29 11:28:14] DEBUG[14333] config.c: extract uint from [60] in [0, 86400] gives [60](0)
[2018-12-29 11:28:14] DEBUG[14333] res_pjsip_registrar.c: Refreshed contact 'sip:[email protected]:5060' on AOR '701' with new expiration of 3600 seconds
[2018-12-29 11:28:14] DEBUG[14333] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0)
[2018-12-29 11:28:14] DEBUG[14333] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[2018-12-29 11:28:14] DEBUG[14333] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0)
[2018-12-29 11:28:14] DEBUG[14333] config.c: extract uint from [5060] in [0, 4294967295] gives [5060](0)
[2018-12-29 11:28:14] DEBUG[14333] config.c: extract uint from [60] in [0, 86400] gives [60](0)
[2018-12-29 11:28:14] DEBUG[14333] netsock2.c: Splitting '192.168.0.137' into...
[2018-12-29 11:28:14] DEBUG[14333] netsock2.c: ...host '192.168.0.137' and port ''.
[2018-12-29 11:28:14] DEBUG[14333] res_pjsip_nat.c: Request is being sent to local address, skipping NAT manipulation
[2018-12-29 11:28:14] VERBOSE[14333] res_pjsip_logger.c: <--- Transmitting SIP response (432 bytes) to UDP:192.168.0.137:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.137:5060;rport=5060;received=192.168.0.137;branch=z9hG4bK3289336715
Call-ID: [email protected]
From: "701" <sip:[email protected]>;tag=4197363148
To: "701" <sip:[email protected]>;tag=z9hG4bK3289336715
CSeq: 6 REGISTER
Date: Sat, 29 Dec 2018 17:28:14 GMT
Contact: <sip:[email protected]:5060>;expires=3599
Expires: 3600
Server: FPBX-14.0.5.5(13.22.0)
Content-Length:  0


[2018-12-29 11:28:14] DEBUG[2270] threadpool.c: Increasing threadpool Sorcery's size by 1
[2018-12-29 11:28:14] DEBUG[19751] manager.c: Examining AMI event:
Event: SuccessfulAuth
Privilege: security,all
EventTV: 2018-12-29T11:28:14.991-0600
Severity: Informational
Service: PJSIP
EventVersion: 1
AccountID: 701
SessionID: [email protected]
LocalAddress: IPV4/UDP/192.168.0.35/5060
RemoteAddress: IPV4/UDP/192.168.0.137/5060
UsingPassword: 1


[2018-12-29 11:28:14] DEBUG[14623] res_pjsip_mwi.c: Sending unsolicited MWI NOTIFY to endpoint 701, new messages: 0, old messages: 0
[2018-12-29 11:28:14] DEBUG[14623] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0)
[2018-12-29 11:28:14] DEBUG[14623] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[2018-12-29 11:28:14] DEBUG[14623] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0)
[2018-12-29 11:28:14] DEBUG[14623] config.c: extract uint from [5060] in [0, 4294967295] gives [5060](0)
[2018-12-29 11:28:14] DEBUG[14623] config.c: extract uint from [60] in [0, 86400] gives [60](0)
[2018-12-29 11:28:14] DEBUG[14623] res_pjsip.c: 0x7fdc781f6450: Wrapper created
[2018-12-29 11:28:14] DEBUG[14623] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 192.168.0.35:5060 (this may be re-written again later)
[2018-12-29 11:28:14] DEBUG[14623] netsock2.c: Splitting '192.168.0.137' into...
[2018-12-29 11:28:14] DEBUG[14623] netsock2.c: ...host '192.168.0.137' and port ''.
[2018-12-29 11:28:14] DEBUG[14623] res_pjsip_nat.c: Request is being sent to local address, skipping NAT manipulation
[2018-12-29 11:28:14] VERBOSE[14623] res_pjsip_logger.c: <--- Transmitting SIP request (632 bytes) to UDP:192.168.0.137:5060 --->
NOTIFY sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.35:5060;rport;branch=z9hG4bKPj78193837-cb5f-4fbd-94c1-5d94b8372626
From: <sip:[email protected]>;tag=1723ae2c-116b-448a-bca9-2a9067a0e3a5
To: <sip:[email protected]>
Contact: <sip:[email protected]:5060>
Call-ID: 7a5dac9a-dfa8-4626-85f2-a11308ff7af1
CSeq: 28643 NOTIFY
Subscription-State: terminated
Event: message-summary
Allow-Events: presence, dialog, message-summary, refer
Max-Forwards: 70
User-Agent: FPBX-14.0.5.5(13.22.0)
Content-Type: application/simple-message-summary
Content-Length:    48

Messages-Waiting: no
Voice-Message: 0/0 (0/0)

The syslog from the phone pretty much mirrors what I am seeing from the asterisk debug log. ie ‘Hey there are messages oh wait there are not’. Happy to post those if anyone would like to see them.

BlazeStudios · December 29, 2018, 8:48pm

OK so now show that voicemail INBOX

ls -l /var/spool/asterisk/voicemail/default/701/INBOX

As well show screenshot(s) of the Advanced tab of extension 701.

Ollie · December 29, 2018, 9:45pm

[root@freepbx ~]# ls -l /var/spool/asterisk/voicemail/default/701/INBOX/
total 1720
-rw-rw-r-- 1 asterisk asterisk    327 Dec 21 11:12 msg0000.txt
-rw-rw-r-- 1 asterisk asterisk 620204 Dec 21 11:12 msg0000.wav
-rw-rw-r-- 1 asterisk asterisk    304 Dec 22 16:24 msg0001.txt
-rw-rw-r-- 1 asterisk asterisk  73644 Dec 22 16:24 msg0001.wav
-rw-rw-rw- 1 asterisk asterisk    328 Dec 22 20:50 msg0002.txt
-rw-r--r-- 1 asterisk asterisk 511404 Dec 22 20:50 msg0002.wav
-rw-rw-rw- 1 asterisk asterisk    334 Dec 28 16:15 msg0003.txt
-rw-r--r-- 1 asterisk asterisk 533804 Dec 28 16:15 msg0003.wav

BlazeStudios · December 29, 2018, 10:05pm

Set the MWI Subscription to “Solicited” and see what that does.

Ollie · January 6, 2019, 8:08am

Well that appears to have cleared it up. Setting it to "solicited’ survives multiple reboots without losing MWI for hours on end. Switching back to ‘auto’ and reboot, MWI disappears within a few hours.

Is there any negative to leaving this setting on solicited? I only ask as the help prompt mentions not switching from auto unless there are error messages in log and there are not.

tonyclewis · January 6, 2019, 1:27pm

Auto is suppose to detect what the phone expects where when you set it to Solicit you are specifically setting the type. If that works for your devices then no harm at all in setting it.

Ollie · January 9, 2019, 4:55pm

Thanks @tonyclewis, and a huge thanks again to @BlazeStudios for helping me through this. I’ve set all extensions to solicited now so hopefully that is the end of it.

On a slightly curious note, Yealink support mailed me this:

Hello Customer, good day!

I got the update from our R&amp;D. This issue was caused by server side, as follows.

**At 15:38:36** , the phone received "yes" notify.

Dec 22 15:38:36 192.168.0.137 Dec 22 15:38:36 sua [1333]: DLG &lt;6+info  &gt; [000] Messages-Waiting: yes  

Dec 22 15:38:36 192.168.0.137 Dec 22 15:38:36 sua [1333]: DLG &lt;6+info  &gt; [000] Voice-Message: 1/0 (0/0)  

**But at 15:38:38** , the phone received "no" notify.

Dec 22 15:38:38 192.168.0.137 Dec 22 15:38:36 sua [1333]: DLG &lt;6+info  &gt; [000] Messages-Waiting: no 

Dec 22 15:38:38 192.168.0.137 Dec 22 15:38:36 sua [1333]: DLG &lt;6+info  &gt; [000] Voice-Message: 0/0 (0/0)  

The phone is only a terminal, so it will only decide whether to pop up the window notification according to the notify message. "yes" means the notification will be turned on.

In addition, the CSeq value of notify was wrong. For example, the phone received two notify messages at 14:48:37.

One was CSeq: 61346 NOTIFY, the other one was CSeq: 31264 NOTIFY. Normally, the next cseq value will be one greater than the previous one for the same account. 

For this, can you please contact your server provider for help first? Please let me know if any update about the result of this case, thanks in advance!

Mainly his mention of the CSeq value being abnormal. Anything I should be digging into there?

tm1000 · January 9, 2019, 5:15pm

Unfortunately there’s nothing you can do. This is a known issue

scott.imn · November 11, 2019, 9:50pm

Thanks BlazeStudios for the suggestion.

I appear to be having this same problem across multiple systems with Digium D60 / D6x phones. From initial testing, setting the MWI Subscription to Solicited (in Extension > Advanced) seems to resolve the issue.

I captured the PBX sending a SIP notice to the phone that it had no messages.

slonkak · December 7, 2021, 7:14pm

Hey Andrew, would you mind sharing the URL to this specific bug report (I’m having a hard time finding it) so I can track it? I’m having similar issues on random phones at random remote locations and would like to follow when it gets fixed. Thanks, everyone, for all of the troubleshooting tips!

BlazeStudios · December 7, 2021, 10:52pm

I’m not sure how a bug report from 2018 is going to be relevant at the end of 2021 and different versions being current.

Also, please don’t resurrect zombie threads.

lgaetz · January 6, 2022, 10:53pm

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