NO JOY Voicemail MWI (Message Waiting Indicator light) random delay

[domiflichi]

Hello,

I have a fairly fresh, and up-to-date Incredible PBX 13-13 system (on actual hardware - not a VM).

I've got 3 phones (Snom 320s) connected to the system currently (more later) and I've noticed a problem with the voicemail notification light. When a voicemail is left for that extension, sometimes the light will start blinking properly right away, sometimes there will be a delay of a few minutes to around half an hour. It seems fairly random. And similarly, once the voicemail is checked, the light will sometimes stop blinking right away, sometimes it will take a few minutes before it stops, sometimes it will be around half an hour before it stops blinking.

I can go into the Snom's web interface and force the extension to re-register and this seems to update the light immediately.

The voicemail notification email gets sent immediately every time.

I don't think it's the phones because the same phones are also on an older PBX-In-A-Flash system and the lights 'update' immediately every time for those extensions.

 

[islandtech]

On my install of 13-13 for a new client I've noticed the same but with GrandStream and Yealink.
Had to install 13-12 to meet my deadline
Just finished another (latest) 13-13 and will be testing later

 

[islandtech]

mwi appears to be working as expected on Incredible 13-13.8

 

[wardmundy]

And now there's 13-13.10.

 

[domiflichi]

I just looked at my 'pbxstatus' and I have 13-13.8. So something seems to be wrong with my system in particular...any hints on the kind(s) of things I should look at to get it working?

 

[wardmundy]

I just looked at my 'pbxstatus' and I have 13-13.8. So something seems to be wrong with my system in particular...any hints on the kind(s) of things I should look at to get it working?

Add the new FreePBX modules and see if that doesn't fix your issue. Tutorial here. Let us know how it goes.

 

[domiflichi]

Thanks for the suggestion. Followed the instructions to upgrade the modules, rebooted, but still no joy.

 

[domiflichi]

Not sure if this helps at all, but I'm putting a piece of a log from one of the Snom phones below. I have the log level set to 7 currently.

So I left a voicemail then immediately cleared the log. One thing to note is that this phone has 2 SIP extensions registered, both with the same extension #, 115. The main one is to 10.10.10.200 (this is our old/existing PiAf system), the one that's having the issue is to 10.10.10.198 which is the new Incredible PBX system that I'm talking about in this thread.

[5] 6/3/2019 09:53:41: send lldp advertisment
[6] 6/3/2019 09:54:03: webserver::request 19: GET /log.htm HTTP/1.1
[5] 6/3/2019 09:54:41: send lldp advertisment
[5] 6/3/2019 09:55:41: send lldp advertisment
[5] 6/3/2019 09:56:41: send lldp advertisment
[5] 6/3/2019 09:57:41: send lldp advertisment
[5] 6/3/2019 09:58:41: send lldp advertisment
[5] 6/3/2019 09:59:41: send lldp advertisment
[5] 6/3/2019 10:00:41: send lldp advertisment
[5] 6/3/2019 10:00:49: sip::process_auth:Match challenge for user=115, realm=asterisk
[5] 6/3/2019 10:01:07: Resetting SRTP
[5] 6/3/2019 10:01:07: rtp_port::set_destination  adr=10.10.10.200:16996
[6] 6/3/2019 10:01:07: find_function_key_for_uri: Looking to match sip:[email protected]:2173;line=du9hqff0
[6] 6/3/2019 10:01:07: find_function_key_for_uri: Looking to match Unknown <sip:[email protected]>
[6] 6/3/2019 10:01:07: Line-Seize subscription was not sent
[5] 6/3/2019 10:01:07: Dialog -10/8 going to early
[7] 6/3/2019 10:01:07: GUI: set_led: nr 13 id 14 state 3
[7] 6/3/2019 10:01:07: GUI: set_led: nr 0 id 13 state 3
[5] 6/3/2019 10:01:07: rtp_port::set_port
[5] 6/3/2019 10:01:14: Dialog -10/8 going to terminated
[5] 6/3/2019 10:01:14: rtp_port::set_destination RP-10 adr=
[7] 6/3/2019 10:01:14: GUI: set_led: nr 13 id 14 state 0
[7] 6/3/2019 10:01:14: GUI: set_led: nr 0 id 13 state 0
[5] 6/3/2019 10:01:14: set_audible: RP-10 changed=0, update_req=1, adr=
[5] 6/3/2019 10:01:41: send lldp advertisment
[5] 6/3/2019 10:02:31: sip::process_auth:Match challenge for user=115, realm=asterisk
[5] 6/3/2019 10:02:41: send lldp advertisment
[5] 6/3/2019 10:03:41: send lldp advertisment
[5] 6/3/2019 10:04:34: sip::process_auth:Match challenge for user=115, realm=asterisk
[5] 6/3/2019 10:04:41: send lldp advertisment
[5] 6/3/2019 10:05:41: send lldp advertisment
[5] 6/3/2019 10:06:41: send lldp advertisment
[5] 6/3/2019 10:07:41: send lldp advertisment
[5] 6/3/2019 10:08:41: send lldp advertisment
[5] 6/3/2019 10:09:04: sip::process_auth:Match challenge for user=115, realm=asterisk
[5] 6/3/2019 10:09:19: sip::process_auth:Match challenge for user=115, realm=asterisk
[5] 6/3/2019 10:09:41: send lldp advertisment
[5] 6/3/2019 10:10:16: sip::process_auth:Match challenge for user=115, realm=asterisk
[5] 6/3/2019 10:10:41: send lldp advertisment
[5] 6/3/2019 10:10:49: sip::process_auth:Match challenge for user=115, realm=asterisk
[5] 6/3/2019 10:11:41: send lldp advertisment
[5] 6/3/2019 10:12:22: sip::process_auth:Match challenge for user=115, realm=asterisk
[5] 6/3/2019 10:12:41: send lldp advertisment
[5] 6/3/2019 10:13:41: send lldp advertisment
[5] 6/3/2019 10:14:41: send lldp advertisment
[5] 6/3/2019 10:15:41: send lldp advertisment
[5] 6/3/2019 10:16:23: sip::process_auth:Match challenge for user=115, realm=asterisk
[5] 6/3/2019 10:16:41: send lldp advertisment
[5] 6/3/2019 10:17:06: sip::process_auth:Match challenge for user=115, realm=asterisk
[5] 6/3/2019 10:17:26: sip::process_auth:Match challenge for user=115, realm=asterisk
[5] 6/3/2019 10:17:41: send lldp advertisment
[5] 6/3/2019 10:18:41: send lldp advertisment
[5] 6/3/2019 10:19:41: send lldp advertisment
[5] 6/3/2019 10:20:41: send lldp advertisment
[7] 6/3/2019 10:20:46: NTP: on_ntp_packet() 1: start
[7] 6/3/2019 10:20:46: NTP: on_ntp_packet() 2: resend.pending
[7] 6/3/2019 10:20:46: NTP: on_ntp_packet() 3: refresh.callback timeout after 3600 seconds
[2] 6/3/2019 10:20:45: start_dst(1552183200) end_dst(1572746400) offset_dst(3600) offset_utc(-28800)
[2] 6/3/2019 10:20:45: start DST: 03/10/2019 02:00:00 (1552183200)
[2] 6/3/2019 10:20:45: end DST: 11/03/2019 02:00:00 (1572746400)
[6] 6/3/2019 10:20:46: SIP: reregister timer for line 0 set to 300s
[7] 6/3/2019 10:20:46: Trusted IP Addresses: udp:10.10.10.200
[5] 6/3/2019 10:20:46: sip::process_auth:Match challenge for user=115, realm=asterisk
[2] 6/3/2019 10:20:46: Registered at registrar as [email protected] (Expires: 3600 secs)
[7] 6/3/2019 10:20:46: settings::Set: outgoing_identity = '1', set.need_apply: 0, finished: 1, need reboot to apply: 0
[7] 6/3/2019 10:20:46: settings::Set: outgoing_identity = '2', set.need_apply: 0, finished: 1, need reboot to apply: 0
[6] 6/3/2019 10:20:46: SIP: reregister timer for line 1 set to 300s
[7] 6/3/2019 10:20:46: Trusted IP Addresses: udp:10.10.10.198
[5] 6/3/2019 10:20:46: sip::process_auth:Match challenge for user=115, realm=asterisk
[2] 6/3/2019 10:20:46: Registered at registrar as [email protected] (Expires: 3600 secs)
[7] 6/3/2019 10:20:46: settings::Set: outgoing_identity = '1', set.need_apply: 0, finished: 1, need reboot to apply: 0
[7] 6/3/2019 10:20:46: settings::Set: outgoing_identity = '2', set.need_apply: 0, finished: 1, need reboot to apply: 0
[7] 6/3/2019 10:20:46: GUI: set_led: nr 0 id 13 state 4
[5] 6/3/2019 10:20:48: sip::process_auth:Match challenge for user=115, realm=asterisk
[5] 6/3/2019 10:21:40: send lldp advertisment
[6] 6/3/2019 10:22:40: webserver::request 20: GET /log.htm HTTP/1.1

So I left the voicemail at around 9:53, and the light didn't start flashing until around 10:20. It seems to correspond to the 'Registered at registrar as [email protected]' line, which isn't that surprising given that I can force the phone to re-register from the web interface which seems to trigger the voicemail light

 

[domiflichi]

So I used the same phone for my next little test. I cleared the phone's log, then left myself a voicemail on the 1st line (the one that is connected to our older PBX-In-A-Flash system), and copied the phone's log:

[5] 7/3/2019 15:52:12: rtp_port::set_port
[6] 7/3/2019 15:52:12: Line-Seize subscription was not sent
[7] 7/3/2019 15:52:12: GUI: set_led: nr 13 id 14 state 1
[6] 7/3/2019 15:52:13: Hook switch released
[5] 7/3/2019 15:52:13: set_audible: RP30 changed=1, update_req=0, adr=
[6] 7/3/2019 15:52:13: set_additional_addresses
[5] 7/3/2019 15:52:13: Dialog 30/80 going to trying
[7] 7/3/2019 15:52:13: settings::apply_value: callrecord_dialed_remote = '*115', set.need_apply: 0, finished: 1, need reboot to apply: 0
[7] 7/3/2019 15:52:13: settings::apply_value: callrecord_dialed_time = ' 3:52PM', set.need_apply: 0, finished: 1, need reboot to apply: 0
[7] 7/3/2019 15:52:13: settings::apply_value: callrecord_dialed_duration = ' 0:00', set.need_apply: 0, finished: 1, need reboot to apply: 0
[7] 7/3/2019 15:52:13: settings::apply_value: callrecord_dialed_local = '[email protected]', set.need_apply: 0, finished: 1, need reboot to apply: 0
[7] 7/3/2019 15:52:13: settings::apply_value: callrecord_dialed_duration = ' 0:29', set.need_apply: 0, finished: 1, need reboot to apply: 0
[7] 7/3/2019 15:52:13: settings::apply_value: callrecord_dialed_remote = '*97', set.need_apply: 0, finished: 1, need reboot to apply: 0
[7] 7/3/2019 15:52:13: settings::apply_value: callrecord_dialed_time = ' 3:48PM', set.need_apply: 0, finished: 1, need reboot to apply: 0
[7] 7/3/2019 15:52:13: settings::apply_value: callrecord_dialed_duration = ' 0:08', set.need_apply: 0, finished: 1, need reboot to apply: 0
[7] 7/3/2019 15:52:13: settings::apply_value: callrecord_dialed_remote = '1120', set.need_apply: 0, finished: 1, need reboot to apply: 0
[7] 7/3/2019 15:52:13: settings::apply_value: callrecord_dialed_time = ' 5:56AM', set.need_apply: 0, finished: 1, need reboot to apply: 0
[7] 7/3/2019 15:52:13: settings::apply_value: callrecord_dialed_duration = ' 0:00', set.need_apply: 0, finished: 1, need reboot to apply: 0
[7] 7/3/2019 15:52:13: settings::apply_value: callrecord_dialed_remote = '*80112', set.need_apply: 0, finished: 1, need reboot to apply: 0
[7] 7/3/2019 15:52:13: settings::apply_value: callrecord_dialed_time = ' 5:55AM', set.need_apply: 0, finished: 1, need reboot to apply: 0
[7] 7/3/2019 15:52:13: settings::apply_value: callrecord_dialed_duration = ' 0:01', set.need_apply: 0, finished: 1, need reboot to apply: 0
[5] 7/3/2019 15:52:14: sip::process_auth:Match challenge for user=115, realm=asterisk
[5] 7/3/2019 15:52:14: Dialog 30/80 going to proceeding
[5] 7/3/2019 15:52:14: Dialog 30/80 going to confirmed
[2] 7/3/2019 15:52:14: SIP: Process timer without requiring timer
[2] 7/3/2019 15:52:14: SIP: Session timer refresh 1800 sec by remote
[5] 7/3/2019 15:52:14: Resetting SRTP
[5] 7/3/2019 15:52:14: rtp_port::set_destination RP30 adr=10.10.10.200:18484
[5] 7/3/2019 15:52:14: set_audible: RP30 changed=0, update_req=1, adr=10.10.10.200:18484
[6] 7/3/2019 15:52:32: Hook switch pressed
[7] 7/3/2019 15:52:32: settings::apply_value: callrecord_dialed_duration = ' 0:18', set.need_apply: 0, finished: 1, need reboot to apply: 0
[5] 7/3/2019 15:52:32: Dialog 30/80 going to terminated
[0] 7/3/2019 15:52:32: Deleting connected_call
[7] 7/3/2019 15:52:32: GUI: set_led: nr 13 id 14 state 0
[6] 7/3/2019 15:52:32: SIP: packet 1007647 stopped retransmission
[6] 7/3/2019 15:52:32: SIP: packet 1007649 stopped retransmission
[5] 7/3/2019 15:52:32: set_audible: RP30 changed=1, update_req=0, adr=10.10.10.200:18484
[5] 7/3/2019 15:52:32: set_audible: RP30 changed=0, update_req=0, adr=10.10.10.200:18484
[7] 7/3/2019 15:52:32: GUI: set_led: nr 0 id 13 state 4
[6] 7/3/2019 15:52:44: webserver::request 65: GET /log.htm HTTP/1.1

The MWI light comes on immediately (as always, and as expected). Not sure if this is helpful...I know I can't really make any sense of it.