Summary:	ASTERISK-28306: res_pjsip_mwi: MWI NOTIFY occasionally takes minutes to be sent
Reporter:	Jared Hull (fortytwo)	Labels:	pjsip
Date Opened:	2019-02-25 18:01:18.000-0600	Date Closed:	2019-03-15 18:31:51
Priority:	Major	Regression?
Status:	Closed/Complete	Components:	Applications/app_voicemail Resources/res_pjsip_mwi
Versions:	16.2.0	Frequency of Occurrence	Occasional
Related Issues:	is related to ASTERISK-28340 MWI NOTIFY is not sent immediately after a VM was created/deleted
Environment:		Attachments:	( 0) extensions.conf ( 1) pjsip.conf ( 2) voicemail_send.txt ( 3) voicemail.conf
Description:	I am dialing *0103 from extension 103 to leave a voicemail message for extension 103. In the attached voicemail_send.txt, it takes 4 minutes from the time I hang up the phone to the time the MWI NOTIFY packet is sent. Sometimes it is near instant for 10 calls in a row, sometimes it only takes a minute, occasionally it takes too long for my customer's liking. Log starts when the call is made. Line 1402 - The call is hung up. {noformat}[Feb 25 22:52:21] VERBOSE[15281]{noformat} Line 2126 - MessageWaiting AMI event {noformat}[Feb 25 22:52:28] DEBUG[15278]{noformat} Line 2514 - The voicemail.conf externnotify script is executed for the first time. This executes asterisk -rx "devstate change Custom:vm103 BUSY" {noformat}[Feb 25 22:52:28] DEBUG[15363] app_voicemail.c: Executing sh /voipprovider_scripts/voicemail_notify.sh "" 103@voicemail 1 0 0 & {noformat} Line 2842 - Another MessageWaiting AMI event is sent, the voicemail.conf externnotify script is executed again?, channels soft hangup, and the hangup handler begins. Watching the dialplan in the CLI, it is very noticeable that there is a 10 second delay from the time I hang up the phone to the time that the hangup handler begins. This short delay happens every time on Asterisk 16.2 and I don't recall it on 14.6, but it only happens after voicemail() has actually recorded a voicemail so maybe there is just a bit of latency when writing the voicemail to our NAS which in this case is 38ms away in another datacenter. This delay is not in itself impactful and may or may not be related to the (occasionally) very slow NOTIFYs that I am seeing. {noformat}[Feb 25 22:52:32] DEBUG[15902][C-00000002] app_voicemail.c: Queueing event for mailbox 103@voicemail  New: 1   Old: 0 {noformat} Line 26289 - The NOTIFY is finally sent to the phone, nearly 4 minutes later. {noformat}[Feb 25 22:56:11] VERBOSE[15283]{noformat}
Comments:	By: Asterisk Team (asteriskteam) 2019-02-25 18:01:18.829-0600 Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution. A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report. Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process]. Please note that once your issue enters an open state it has been accepted. As Asterisk is an open source project there is no guarantee or timeframe on when your issue will be looked into. If you need expedient resolution you will need to find and pay a suitable developer. Asking for an update on your issue will not yield any progress on it and will not result in a response. All updates are posted to the issue when they occur. By: Joshua C. Colp (jcolp) 2019-02-26 04:54:45.225-0600 What is the voicemail.conf that exhibits the problem and the dialplan logic? By: Jared Hull (fortytwo) 2019-02-26 09:44:39.026-0600 Attached extensions.conf, and voicemail.conf, and pjsip.conf By: George Joseph (gjoseph) 2019-02-26 12:28:28.461-0600 Jared, It appears that this issue is caused by some interaction between app_voicemail and res_pjsip_mwi, possibly by reloading voicemail.  When this issue happens, can you do a {{module reload res_pjsip_mwi.so}} and see if that restores the notifies?   Just FYI... The "delay" isn't really a delay.  When you get in this situation, res_pjsip_mwi is not getting triggered to send NOTIFYs but when a client re-registers, they automatically get a NOTIFY that catches them up. By: Jared Hull (fortytwo) 2019-02-26 13:23:39.062-0600 Our registration cycles are 5-10 minutes, so that explains why "delay" times I saw were changing. When I reload res_pjsip_mwi, it instantly sends MWI NOTIFYs and from that point on any new voicemails will as well. I can cause the issue to happen again by doing a {{core reload}}. Until I reload res_pjsip_mwi again, MWI NOTIFYs are not sent out until they sync up when an extension re-registers. In addition to new voicemail messages during the problematic state, it seems that deleting messages through the VoicemailMain() application does not send MWI either. A core reload will reload res_pjsip_mwi.so before app_voicemail.so, could this be part of the problem? I have autoload=yes in my modules.conf, if that even applies to module reload order. By: Jared Hull (fortytwo) 2019-02-26 13:39:13.322-0600 I should also add that a second {{core reload}} does not fix the issue, even though res_pjsip_mwi is reloaded during that reload. I can also cause this issue to happen when I {{module reload app_voicemail.so}}, so it isn't the actually core reload. It looks to be caused by app_voicemail being reloaded after res_pjsip_mwi. By: Friendly Automation (friendly-automation) 2019-03-15 18:31:52.874-0500 Change 11116 merged by George Joseph: app.c:  Remove deletion of pool topic on mwi state delete [https://gerrit.asterisk.org/c/asterisk/+/11116|https://gerrit.asterisk.org/c/asterisk/+/11116] By: Friendly Automation (friendly-automation) 2019-03-15 18:32:01.537-0500 Change 11115 merged by George Joseph: app.c:  Remove deletion of pool topic on mwi state delete [https://gerrit.asterisk.org/c/asterisk/+/11115|https://gerrit.asterisk.org/c/asterisk/+/11115] By: Friendly Automation (friendly-automation) 2019-03-15 18:32:09.983-0500 Change 11114 merged by George Joseph: app.c:  Remove deletion of pool topic on mwi state delete [https://gerrit.asterisk.org/c/asterisk/+/11114|https://gerrit.asterisk.org/c/asterisk/+/11114]