FreePBX | Register | Issues | Wiki | Portal | Support

Voicemail notification and MWI erratic behavior


(Tom Ray) #21

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

  1. SSH into the PBX and do yum install sngrep
  2. From the system cli just run sngrep
  3. 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.
  4. 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.


#22

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:701@192.168.0.137:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.35:5060;rport;branch=z9hG4bKPj783f1824-3df9-41eb-8e7f-afdac49ab95b
From: <sip:701@192.168.0.35>;tag=dba2cd6b-0fe0-4253-a6e0-b428a927493e
To: <sip:701@192.168.0.137>
Contact: <sip:701@192.168.0.35: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:701@192.168.0.35>;tag=dba2cd6b-0fe0-4253-a6e0-b428a927493e
To: <sip:701@192.168.0.137>;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:701@192.168.0.137:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.35:5060;rport;branch=z9hG4bKPj1ab9ab2b-e30c-4362-9d06-d2fba14e2f6e
From: <sip:701@192.168.0.35>;tag=79062b52-3a13-4066-9165-8b1de59504d9
To: <sip:701@192.168.0.137>
Contact: <sip:701@192.168.0.35: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:701@192.168.0.35>;tag=79062b52-3a13-4066-9165-8b1de59504d9
To: <sip:701@192.168.0.137>;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:701@192.168.0.137:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.35:5060;rport;branch=z9hG4bKPj8bc8380c-3cc7-4d6e-a7d8-4a558a47616b
From: <sip:701@192.168.0.35>;tag=8ada3409-76ee-40d9-a9b4-5f5583bc002a
To: <sip:701@192.168.0.137>
Contact: <sip:701@192.168.0.35: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:701@192.168.0.35>;tag=8ada3409-76ee-40d9-a9b4-5f5583bc002a
To: <sip:701@192.168.0.137>;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:701@192.168.0.137:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.35:5060;rport;branch=z9hG4bKPj6b9555e8-7580-49ed-a766-6713ecf7b444
From: <sip:701@192.168.0.35>;tag=882c44e4-6ff7-4e70-b6c0-ca78e22f66f7
To: "701" <sip:701@192.168.0.35>;tag=3963180513
Contact: <sip:192.168.0.35:5060>
Call-ID: 0_1411311281@192.168.0.137
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:701@192.168.0.35:5060>;tag=4197363148
To: "701" <sip:701@192.168.0.35:5060>
Call-ID: 0_2163194066@192.168.0.137
CSeq: 3 REGISTER
Contact: <sip:701@192.168.0.137: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: 0_2163194066@192.168.0.137
From: "701" <sip:701@192.168.0.35>;tag=4197363148
To: "701" <sip:701@192.168.0.35>;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: 0_2163194066@192.168.0.137
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:701@192.168.0.35>;tag=882c44e4-6ff7-4e70-b6c0-ca78e22f66f7
To: "701" <sip:701@192.168.0.35>;tag=3963180513
Call-ID: 0_1411311281@192.168.0.137
CSeq: 21193 NOTIFY
Contact: <sip:701@192.168.0.137: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:701@192.168.0.35:5060>;tag=4197363148
To: "701" <sip:701@192.168.0.35:5060>
Call-ID: 0_2163194066@192.168.0.137
CSeq: 4 REGISTER
Contact: <sip:701@192.168.0.137: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:701@192.168.0.137: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: 0_2163194066@192.168.0.137
From: "701" <sip:701@192.168.0.35>;tag=4197363148
To: "701" <sip:701@192.168.0.35>;tag=z9hG4bK3164244746
CSeq: 4 REGISTER
Date: Sat, 29 Dec 2018 16:38:14 GMT
Contact: <sip:701@192.168.0.137: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: 0_2163194066@192.168.0.137
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:701@192.168.0.137:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.35:5060;rport;branch=z9hG4bKPj8bc8380c-3cc7-4d6e-a7d8-4a558a47616b
From: <sip:701@192.168.0.35>;tag=8ada3409-76ee-40d9-a9b4-5f5583bc002a
To: <sip:701@192.168.0.137>
Contact: <sip:701@192.168.0.35: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)

#23

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:701@192.168.0.137:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.35:5060;rport;branch=z9hG4bKPj78193837-cb5f-4fbd-94c1-5d94b8372626
From: <sip:701@192.168.0.35>;tag=1723ae2c-116b-448a-bca9-2a9067a0e3a5
To: <sip:701@192.168.0.137>
Contact: <sip:701@192.168.0.35: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:701@192.168.0.35>;tag=1723ae2c-116b-448a-bca9-2a9067a0e3a5
To: <sip:701@192.168.0.137>;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:701@192.168.0.137:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.35:5060;rport;branch=z9hG4bKPj29dfd21d-b215-4f63-8ead-2ec3195f21b6
From: <sip:701@192.168.0.35>;tag=882c44e4-6ff7-4e70-b6c0-ca78e22f66f7
To: "701" <sip:701@192.168.0.35>;tag=3963180513
Contact: <sip:192.168.0.35:5060>
Call-ID: 0_1411311281@192.168.0.137
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:701@192.168.0.35:5060>;tag=4197363148
To: "701" <sip:701@192.168.0.35:5060>
Call-ID: 0_2163194066@192.168.0.137
CSeq: 5 REGISTER
Contact: <sip:701@192.168.0.137: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: 0_2163194066@192.168.0.137
From: "701" <sip:701@192.168.0.35>;tag=4197363148
To: "701" <sip:701@192.168.0.35>;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: 0_2163194066@192.168.0.137
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:701@192.168.0.35>;tag=882c44e4-6ff7-4e70-b6c0-ca78e22f66f7
To: "701" <sip:701@192.168.0.35>;tag=3963180513
Call-ID: 0_1411311281@192.168.0.137
CSeq: 21194 NOTIFY
Contact: <sip:701@192.168.0.137: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:701@192.168.0.35:5060>;tag=4197363148
To: "701" <sip:701@192.168.0.35:5060>
Call-ID: 0_2163194066@192.168.0.137
CSeq: 6 REGISTER
Contact: <sip:701@192.168.0.137: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:701@192.168.0.137: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: 0_2163194066@192.168.0.137
From: "701" <sip:701@192.168.0.35>;tag=4197363148
To: "701" <sip:701@192.168.0.35>;tag=z9hG4bK3289336715
CSeq: 6 REGISTER
Date: Sat, 29 Dec 2018 17:28:14 GMT
Contact: <sip:701@192.168.0.137: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: 0_2163194066@192.168.0.137
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:701@192.168.0.137:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.35:5060;rport;branch=z9hG4bKPj78193837-cb5f-4fbd-94c1-5d94b8372626
From: <sip:701@192.168.0.35>;tag=1723ae2c-116b-448a-bca9-2a9067a0e3a5
To: <sip:701@192.168.0.137>
Contact: <sip:701@192.168.0.35: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.


(Tom Ray) #24

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.


#25
[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

Thanks Tom.


(Tom Ray) #27

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


#28

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.


(Tony Lewis) #29

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.


#30

Thanks @tlewis, 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?


(Andrew Nagy) #31

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