Summary:	ASTERISK-26548: res_pjsip_pubsub: Subscribe to MWI expires early
Reporter:	Carl Fortin (phonefxg)	Labels:
Date Opened:	2016-11-02 06:54:25	Date Closed:	2016-11-09 08:07:04.000-0600
Priority:	Minor	Regression?
Status:	Closed/Complete	Components:	Resources/res_pjsip_mwi
Versions:	14.1.0	Frequency of Occurrence	Occasional
Related Issues:
Environment:	Asterisk Realtime 14.1 PJSIP Driver mysql Ver 14.14 pjproject 2.5.5 spandsp 0.0.6 jansson 2.7 CentOS 6.6 64 bits on Vmware Phones : Cisco SPA514G FW: 7.5.7 ATA : Audiocodes MP124 T1 : Mediatrix 3532 ISDN CPU : Quadcore Intel(R) Xeon(R) CPU E5-2650 RAM : 8 GB HDD : 35 GB	Attachments:	( 0) astraa6.pcap ( 1) CLI_OUTPUT.txt ( 2) debug_log_mwi_subscription-state.txt ( 3) my_verbose_Log.txt ( 4) myDebugLog_3419.txt ( 5) Sip_MWI_Notify.pcap ( 6) spacfg.xml ( 7) Subscribe_cisco.pcap
Description:	We are using the mailboxes in the AOR table so our Cisco phones can subscribe to Message Waiting Indications. Once in a while the light would not be on even with new messages, so I did a trace with wireshark and found something weird. The phone boots and subscribe sucessfully to MWI with a voicemail subscribe interval of 86400. If I look at my wireshark trace I can see that asterisk sends a sollicited notify 5 times. Is this normal? I have also noticed that the Subscription state is going from 83544 seconds to 432 seconds and it expires in the last notify.
Comments:	By: Asterisk Team (asteriskteam) 2016-11-02 06:54:26.292-0500 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]. By: Carl Fortin (phonefxg) 2016-11-02 07:00:36.675-0500 Wireshark capture of a successful MWI subscription from Cisco Phone to Asterisk By: Carl Fortin (phonefxg) 2016-11-02 07:13:03.242-0500 Detailed info of my endpoint and aor pjsip show endpoint EGCMBNNI [Edit - Removed by admin] By: Carl Fortin (phonefxg) 2016-11-02 07:24:23.666-0500 Wireshark capture of a sollicited notify to Cisco Phone. By: Carl Fortin (phonefxg) 2016-11-02 07:28:33.744-0500 The bug with MWI  that would not light with new messages is intermittent. Sometimes it would light just after checking for new messages. Asterisk always send 5 notify per new message. By: Rusty Newton (rnewton) 2016-11-02 08:31:21.999-0500 Please reserve the comments fields for comments or very short excerpts of debug only. Please attach your debug and CLI output to the issue with a txt extension. By: Rusty Newton (rnewton) 2016-11-02 08:32:54.927-0500 https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information Go ahead and collect two logs during the issue occurring. Gather one with: warning,notice,error,verbose Another with: warning,notice,error,verbose,debug Turn verbose and debug both up to 5. By: Carl Fortin (phonefxg) 2016-11-02 08:39:35.872-0500 CLI output of my aor endpoint and voicemail user By: Carl Fortin (phonefxg) 2016-11-02 08:57:56.929-0500 Debug logs By: Rusty Newton (rnewton) 2016-11-04 16:35:42.511-0500 Sorry, I wasn't explicit enough. Please gather logs just like you did, except make sure the output of "pjsip set logger on" is included inside them. That is, we want to see the SIP trace alongside the various log channels. By: Carl Fortin (phonefxg) 2016-11-05 06:55:47.022-0500 Here is a debug log with PJSIP debug on.If you look at ip address 10.188.4.31, we can clearly see that the Subscription-State: active;expires=415. By: Joshua C. Colp (jcolp) 2016-11-08 08:44:36.215-0600 I don't believe this is a bug in Asterisk. Each of the NOTIFY messages are for different subscriptions. The phone appears to have set up multiple subscriptions, or blindly accepts the NOTIFY of subscriptions from before it was started. What would normally happen is that if the phone receives a NOTIFY for a subscription it no longer knows about it would respond back with a response that would cause the subscription to get terminated. From the side of Asterisk it's just doing what it should - sending a NOTIFY message for each subscription it has and getting a 200 OK back. Do any of these logs show a case where we sent a NOTIFY (or you expected us to) and we didn't? By: Carl Fortin (phonefxg) 2016-11-08 08:54:01.631-0600 Here is my XML from the phone, only line 2 subscribe to voicemail. The setting is called Voice_Mail_Server_1_ Voice_Mail_Server_2_ Voice_Mail_Server_3_ Voice_Mail_Server_4_ Besides there is only 3 lines on the phone, so I don't understand where those other notify are for... By: Carl Fortin (phonefxg) 2016-11-08 09:08:07.899-0600 I think I know what you mean by different subscriptions, the call ID is different for each notify in the PCAP. I really don't understand why Asterisk is doing that , since there is only one subscription to voicemail in the PCAP file coming from the phone By: Joshua C. Colp (jcolp) 2016-11-08 14:26:57.970-0600 Asterisk wouldn't create subscriptions out of thin air. Could they be past subscriptions from before it was started/restarted? As well Asterisk will persist subscriptions across restarts itself. By: Carl Fortin (phonefxg) 2016-11-08 14:30:23.156-0600 Past subscriptions from before? If so ,how can I clear them? Would Reloading a module clear previous possible subscriptions? By: Joshua C. Colp (jcolp) 2016-11-08 14:34:04.028-0600 There is no CLI command to clear them and reloading the module won't. You would need to find them in "database show" and delete them using the "database" CLI commands and then restart Asterisk. That would remove them from persistence. By: Joshua C. Colp (jcolp) 2016-11-08 14:35:03.195-0600 And for example - if your phone is registered and subscribed, and you then restart it - the phone may not terminate the subscription it had. If you keep doing it those subscriptions could pile up. As I previously mentioned normally the phone would reject those NOTIFY messages and the subscription would be terminated, but yours is accepting each and every one. By: Carl Fortin (phonefxg) 2016-11-08 14:46:52.433-0600 Hum I see, it point to a Cisco bug.. I will do more testing to check if they do pile up as well as trying to update to latest firmware. I hope it is not a Cisco bug, because they do not move fast on correcting bugs. By: Joshua C. Colp (jcolp) 2016-11-08 14:50:31.059-0600 I'll leave this in request for feedback for now until you look on your end. By: Carl Fortin (phonefxg) 2016-11-09 08:00:04.400-0600 I did some more tests and after rebooting the phone subscriptions do add up in the astdb database. Is there any way to limit the number of subscriptions allowed? How can the subscriptions from astdb be removed if the phone is disconnected forever. Will it stay in the database forever? By: Joshua C. Colp (jcolp) 2016-11-09 08:04:15.096-0600 There is no mechanism currently to limit the number of subscriptions and they will exist until they expire, or until a NOTIFY receives a fatal response. Other phones will respond with a 481 Call/Transaction Does Not Exist to the other NOTIFY messages causing them to be terminated. By: Carl Fortin (phonefxg) 2016-11-09 08:06:02.017-0600 So basically I'm stuck until I convince Cisco that it's a bug.I'll report the problem to Cisco and see how ti goes. Thank you very much for your great help. By: Carl Fortin (phonefxg) 2017-01-25 09:45:55.901-0600 I did some more tests with another brand (Aastra) and even though the phone send a 481 telling asterisk to terminate the previous subscription, asterisk just ignore the message and keep sending multiple notify. My included pcap with the aastra phone sending the 481 will show you that asterisk do not seem to acknowledge the 481  code. Meanwhile I have open a ticket with Cisco because there's still a bug with the Cisco not sending the 481. Can we reopen this issue to check why asterisk do not terminate subscription when receiving 481. By: Asterisk Team (asteriskteam) 2017-01-25 09:45:56.422-0600 This issue has been reopened as a result of your commenting on it as the reporter. It will be triaged once again as applicable. By: Carl Fortin (phonefxg) 2017-01-25 09:46:40.157-0600 Pcap file of aastra phone sending a 481 to asterisk. By: Rusty Newton (rnewton) 2017-01-25 14:53:28.700-0600 Carl lets open a new issue for the Aastra problem as it seems slightly different. We don't want to make issues murky or confusing back tracking too many issues in one ticket.