Troubleshooting the Message Waiting Indicator

The message waiting indicator (MWI) is one of the most important and basic features of any voice mail system. Sometimes, because of many factors, the subscriber does not see the correct MWI changes on the phone. This could be because somehow Cisco CME and Cisco UE got out of sync with each other concerning the MWI status for subscribers. (For example, perhaps Cisco CME was reloaded and it does not keep track of MWI state across reloads.) This section discusses MWI configuration and troubleshooting MWI-related issues.

MWI Operation

With Cisco CME deployments, Cisco UE uses what is called a callout mechanism to change MWI status on the phone. In this mechanism, Cisco CME defines two special extensions: the MWI ON and MWI OFF DNs. These extension definitions have a very specific number format.

For example, the pattern can be 2222.... for the MWI ON DN and 2221.... for the MWI OFF DN, where 2222 and 2221 are prefixes, and the number of dots is equal to the length of the extensions in your Cisco CME dial plan. If Cisco UE must turn on MWI for extension 6001, it places an outgoing call to number 22226001. Cisco CME terminates the call on the MWI ON DN (because the called number matches the dial peer for the MWI ON DN). Cisco CME processes the called number of the call and extracts extension 6001 from it, which is matched by the four dots defined on the MWI ON DN. It then finds all the phones with appearances of extension 6001 on them (there can be several if 6001 is a shared line), and then sends an SCCP MWI ON message to each of the phones. A similar sequence of steps is followed to turn off an MWI lamp by Cisco UE outcalling to the MWI OFF DN. For example, 22216001 is used to turn off MWI for extension 6001.

You can test the operation of your MWI DNs on Cisco CME by dialing the MWI DN prefix followed by the extension from any phone. For example, if you dial 22226001 from any phone, you should see the MWI light activated on phones with extension 6001. This verifies that your MWI DNs are correctly configured and operational.

When you choose the patterns for MWI DNs, keep in mind that such a pattern must not overlap with any other extension or dial peer patterns configured on Cisco CME. Those configurations can interfere with the MWI calls that come from Cisco UE, effectively breaking MWI operation. Also look for any Cisco IOS translation rules that might translate the called numbers for the MWI DN call. This also breaks the MWI operation.

Now that you understand the mechanism between Cisco CME and Cisco UE for turning MWI on or off, the next step is to investigate what happens inside the Cisco UE software components to affect MWI when a voice message is left in or deleted from a mailbox.

When a new message is left in a mailbox, or a subscriber deletes the last new message in the mailbox, the voice mail system has to change the MWI state on the subscriber's phone. However, the voice mail back-end component does not have access to any call control mechanism to place the outcall to Cisco CME. Instead, it depends on the CRS component, which contains a SIP stack for call control. However, there is no direct interface between the voice mail back end and the CRS component.

The CRS component, as discussed in Chapter 3, can start applications on three kinds of triggers:

• E-mail
• HTTP
• Call

To affect MWI changes, the voice mail system (internally) sends an HTTP trigger to the CRS software. A system-level CRS application called ciscomwiapplication, with an associated script called setMWI.aef, exists and is configured to respond to this HTTP request.

When voice mail sends an HTTP request specifying the extension for MWI operation and the state to be set (ON or OFF), this CRS application starts up and places a call to the appropriate Cisco CME MWI ON or OFF DN using the parameters passed.

Verifying MWI Configuration

For MWI to work correctly, it is important that the configurations on Cisco CME and Cisco UE are correct and match. To verify the configuration, use the commands shown in Example 21-49.

Example 21-49. MWI DN Configuration

ccme#show telephony-service ephone-dn
ephone-dn 20
number 7701
preference 0 secondary 9
huntstop
call-forward busy 5800
call-forward noan 5800 timeout 10
hold-alert 30 originator

ephone-dn 21
number 7010
preference 0 secondary 9
huntstop

ephone-dn 22
number 7011
preference 0 secondary 9
huntstop
call-forward busy 5800
call-forward noan 5800 timeout 10

ephone-dn 23
number 7012
preference 0 secondary 9
huntstop

ephone-dn 50
number 2222.... 
preference 0 secondary 9
huntstop
mwi on 


ephone-dn 51
number 2221.... 
preference 0 secondary 9
huntstop
mwi off 

ephone-dn 61
number 6001
preference 0 secondary 9
huntstop
call-forward all 5800
call-forward busy 5800
call-forward noan 5800 timeout 10

On Cisco UE, ensure that the ciscomwiapplication CRS application is created and configured properly, as shown in Example 21-50.

Example 21-50. MWI Application Configuration on Cisco UE

cue#show ccn application
Name: ciscomwiapplication 
Description: ciscomwiapplication
Script: setmwi.aef
ID number: 0
Enabled: yes 
Maximum number of sessions: 1
strMWI_OFF_DN: 2221 
strMWI_ON_DN: 2222 
CallControlGroupID: 0

Name: voicemail
Description: voicemail
Script: voicebrowser.aef
ID number: 1
Enabled: yes
Maximum number of sessions: 1
logoutUri: http://localhost/voicemail/vxmlscripts/m
bxLogout.jsp
uri: http://localhost/voicemail/vxmlscripts/l
ogin.vxml

Name: autoattendant
Description: autoattendant
Script: aa.aef
ID number: 2
Enabled: yes
Maximum number of sessions: 1
MaxRetry: 3
operExtn: 7701
welcomePrompt: AAWelcome.wav

Name: promptmgmt
Description: promptmgmt
Script: promptmgmt.aef
ID number: 3
Enabled: yes
Maximum number of sessions: 1

You can also verify the current MWI DN settings in the Cisco UE sysDB settings, as shown in Example 21-51. Note that in the output of both the Cisco UE show ccn application (Example 21-50) and show sysdb (Example 21-51) commands, MWI DNs appear without the dots. This does not mean that they are without dots on Cisco CME. (See the output of the show telephony-service ephone-dn command shown earlier in Example 21-49.)

Example 21-51. Verifying MWI DN Configuration on Cisco UE in sysDB

cue#show sysdb /sw/apps/ccn/wf/applications/craAesop/applications/
 ciscomwiapplication
app/applicationId 0
app/applicationType Cisco Script Application
app/description ciscomwiapplication
app/enabled 1
app/maxSessions 8
app/script setmwi.aef
app/aeAccess 0
app/aeEnd 1
cfgVars/strMWI_OFF_DN 2221 
cfgVars/strMWI_ON_DN 2222 
cfgVars/CallControlGroupID 0
cfgVarsType/strMWI_OFF_DN java.lang.String
cfgVarsType/strMWI_ON_DN java.lang.String
cfgVarsType/CallControlGroupID java.lang.Integer

There can be some inconsistency between the Cisco CME and Cisco UE MWI DN configurations if the Cisco CME configuration is changed directly through the Cisco CME GUI or via Cisco IOS CLI. If you see that an inconsistency exists, synchronize both configurations. You can achieve this by navigating to the Administration > Synchronize Information screen in the GUI, as shown in Figure 21-6.

Figure 21-6. Synchronizing MWI Information

If there are any inconsistencies between the Cisco CME and Cisco UE configurations with respect to MWI DNs or other fields, these are listed on the Administration > Synchronize Information page. You must synchronize the information on this screen for the MWI mechanism to work correctly. After you synchronize the information, the MWIs are not automatically refreshed at that time.

You can refresh the MWI states on subscribers' phones in two ways:

• You can refresh a particular subscriber's MWI using the mwi refresh telephonenumber number command in the Cisco UE CLI.
• You can refresh MWI for all the subscribers in your Cisco CME system using the mwi refresh all command.

You can perform both operations via the GUI by navigating to the Voice Mail > Message Waiting Indicators > Refresh screen.

Note

Cisco UE sends an MWI update every time there is a new message in a subscriber's mailbox, not just when there is a state change in a mailbox. Also, Cisco UE does not have the capability to synchronize MWI states automatically at a configured time (or midnight routines), so manual synchronization is a must in case the states get out of synchronization.

One other configuration that can affect MWI operation is the SIP gateway address configuration in Cisco UE. This should point to the Cisco CME with which Cisco UE is integrated. You can verify this setting by using the show ccn subsystem sip Cisco UE CLI command.

Tracing MWI

This section investigates which traces to turn on to troubleshoot MWI-related problems, as well as how to interpret the traces to verify that all the subsystems involved in MWI operation are working correctly. The following trace commands are used to troubleshoot problems in this area:

• trace ccn stacksip dbug
• trace voicemail mwi all
• trace ccn managerappl dbug
• show trace buffer tail

In the traces shown in Example 21-52, extension 5010 has received a new voice message, so the voice mail system sets the MWI state for this extension to true (the ON state). This action by the voice mail system results in an HTTP trigger being sent to the CRS software component, as discussed in the previous sections. In the third line in Example 21-52, you can see the HTTP message going to port 8080, passing the extension number (5010 in this example) and the desired state of the MWI (1 for ON).

Example 21-52. Voice Mail Back End Sends an HTTP Trigger to Turn on MWI

cue#show trace buffer tail
2487 10/01 14:26:54.309 voicemail mwi "setMessageWaiting" 0x0000000000000000 5010,
 true
2487 10/01 14:26:54.309 voicemail mwi " job state" adding job
1792 10/01 14:26:54.309 voicemail mwi "job state" http://localhost: 8080/ 
 mwiapp?extn=5010&state=1 

2317 10/01 14:26:54.316 ACCN APMG 0 TASK_CREATED:Application task created: 
 Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0, 
 desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars= 
 [Lcom.cisco.wfapi.util.WFNameValuePair;@6786a090,script=setmwi.aef]],Application 
 Trigger=ContactApplicationTrigger[time=1065018436314,contact=HttpContact[id=54, 
 type=Cisco Http Contact,implId=null,active=true,state=CONTACT_RECEIVED,
 inbound=true,handled=false,
 locale=en_US,aborting=false,app=App[name=ciscomwiapplication,type=Cisco Script
 Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,
 optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@6786a090,script=
 setmwi.aef]],task=null,session=null,seqNum=-1,time=1065018436314,req=org.apache.
 tomcat.facade.HttpServletRequestFacade@7ce36091]],Task id=16,000,000,031,Task
 Class=com.cisco.wfframework.engine.core.WFEngineWorkflowDebugTask,New Task
 Class=com.cisco.app.impl.WFWorkflowAppDebugTaskWrapper
2317 10/01 14:26:54.317 ACCN APMG 0 APP_SESSION_ACTIVE:Active application session:
 Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,
 desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=
 [Lcom.cisco.wfapi.util.WFNameValuePair;@6786a090,script=setmwi.aef]],Application
 Trigger=ContactApplicationTrigger[time=1065018436314,contact=HttpContact[id=54,
 type=Cisco Http

As shown in the preceding trace, CRS starts its outcalling application in response to the HTTP trigger received from the voice mail component. Example 21-53.is the step-by-step trace of the CRS application executing this operation.

Example 21-53. MWI Application Starts Executing as a Result of the HTTP Trigger

cue#show trace buffer tail
2317 10/01 14:26:54.318 ACCN APMG 0 EXECUTING_STEP:Executing a step:
 Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,
 desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=
 [Lcom.cisco.wfapi.util.WFNameValuePair;@6786a090,script=setmwi.aef]],Task
 id=16,000,000,031,Step id=0,Step Class=com.cisco.wfframework.steps.core.
 StepStart,Step Description=Start
2317 10/01 14:26:54.319 ACCN APMG 0 EXECUTING_STEP:Executing a step:
 Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,
 desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=
 [Lcom.cisco.wfapi.util.WFNameValuePair;@6786a090,script=setmwi.aef]],Task
 id=16,000,000,031,Step id=1,Step Class=com.cisco.wf.steps.ivr.AcceptStep,Step
 Description=Accept (contact: --Triggering Contact--)
2317 10/01 14:26:54.319 ACCN APMG 0 EXECUTING_STEP:Executing a step:
 Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,
 desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=
 [Lcom.cisco.wfapi.util.WFNameValuePair;@6786a090,script=setmwi.aef]],Task
 id=16,000,000,031,Step id=111,Step Class=com.cisco.wf.steps.http.
 GetHttpHeaderStep,Step Description=Get Http Contact Info (contact: --Triggering
 Contact--)
2317 10/01 14:26:54.320 ACCN APMG 0 EXECUTING_STEP:Executing a step:
 Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,
 desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=
 [Lcom.cisco.wfapi.util.WFNameValuePair;@6786a090,script=setmwi.aef]],Task
 id=16,000,000,031,Step id=142,Step Class=com.cisco.wfframework.steps.core.
 StepIf,Step Description=If ( mwistatus != "0" ) Then
2317 10/01 14:26:54.320 ACCN APMG 0 EXECUTING_STEP:Executing a step:
 Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,
 desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=
 [Lcom.cisco.wfapi.util.WFNameValuePair;@6786a090,script=setmwi.aef]],Task
 id=16,000,000,031,Step id=143,Step Class=com.cisco.wfframework.steps.core.
 StepAssign,Step Description=Set strMWI_DN = strMWI_ON_DN
2317 10/01 14:26:54.321 ACCN APMG 0 EXECUTING_STEP:Executing a step:
 Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,
 desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=
 [Lcom.cisco.wfapi.util.WFNameValuePair;@6786a090,script=setmwi.aef]],Task
 id=16,000,000,031,Step id=144,Step Class=com.cisco.wfframework.steps.core.
 StepAssign,Step Description=Set mwiOn = true
2317 10/01 14:26:54.321 ACCN APMG 0 EXECUTING_STEP:Executing a step:
 Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,
 desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=
 [Lcom.cisco.wfapi.util.WFNameValuePair;@6786a090,script=setmwi.aef]],Task
 id=16,000,000,031,Step id=78,Step Class=com.cisco.wfframework.steps.core.StepIf,
 Step Description=If ( mwistatus != "" ) Then
2317 10/01 14:26:54.322 ACCN APMG 0 EXECUTING_STEP:Executing a step:
 Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,
 desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=
 [Lcom.cisco.wfapi.util.WFNameValuePair;@6786a090,script=setmwi.aef]],Task
 id=16,000,000,031,Step id=83,Step Class=com.cisco.wfframework.steps.core.StepIf,
 Step Description=If ( strDeviceNum != "" ) Then
2317 10/01 14:26:54.322 ACCN APMG 0 EXECUTING_STEP:Executing a step:
 Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,
 desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=
 [Lcom.cisco.wfapi.util.WFNameValuePair;@6786a090,script=setmwi.aef]],Task
 id=16,000,000,031,Step id=84,Step Class=com.cisco.wfframework.steps.core.
 StepAssign,Step Description=Set strMWI_CompleteNum = strMWI_DN + strDeviceNum
2317 10/01 14:26:54.322 ACCN APMG 0 EXECUTING_STEP:Executing a step:
 Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,
 desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=
 [Lcom.cisco.wfapi.util.WFNameValuePair;@6786a090,script=setmwi.aef]],Task
 id=16,000,000,031,Step id=189,Step Class=com.cisco.wf.steps.ivr.MWIStep,Step
 Description=Set Message Waiting Indicator (DN: strDeviceNum) 

2317 10/01 14:26:54.323 ACCN APMG 0 EXECUTING_STEP:Executing a step:
 Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,
 desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=
 [Lcom.cisco.wfapi.util.WFNameValuePair;@6786a090,script=setmwi.aef]],Task
 id=16,000,000,031,Step id=193,Step Class=com.cisco.wfframework.steps.core.
 StepComment,Step Description=/* Don't return fail since ... */
2317 10/01 14:26:54.323 ACCN APMG 0 EXECUTING_STEP:Executing a step:
 Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,
 desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=
 [Lcom.cisco.wfapi.util.WFNameValuePair;@6786a090,script=setmwi.aef]],Task
 id=16,000,000,031,Step id=175,Step Class=com.cisco.wf.steps.ivr.CreateCallStep,
Step Description=Place Call (to strMWI_CompleteNum ) 
2317 10/01 14:26:54.329 ACCN SIPL 0 --- send message --- to 1.3.6.29:5060

As a result of the last step, which sets up a call to the value contained in strMWI_CompleteNum, you can see in the traces shown in Example 21-54 that a SIP INVITE message is sent from Cisco UE to Cisco CME to change the state of the MWI lamp.

Example 21-54. Application Execution Results in a SIP Outcall to Cisco CME

cue#trace ccn stacksip dbug
cue#show trace buffer tail
INVITE sip:22225010@1.3.6.29;user=phone SIP/2.0 
Via: SIP/2.0/UDP 1.3.6.129:5060
From: "Cisco SIP Channel5" ;tag=5bed1e99-272
To:  
Call-ID: c91b8616-270@1.3.6.129:5060
CSeq: 51 INVITE
Contact: sip:outbound-0@1.3.6.129:5060
User-Agent: Jasmin UA / ver 1.1
Accept: application/sdp
Content-Type: application/sdp
Content-Length: 216

v=0
o=CiscoSystemsSIP-Workflow-App-UserAgent 2792 2792 IN IP4 1.3.6.129
s=SIP Call
c=IN IP4 1.3.6.129
t=0 0
m=audio 16906 RTP/AVP 0 111
a=rtpmap:0 pcmu/8000
a=rtpmap:111 telephone-event/8000
a=fmtp:111 0-11

2272 10/01 14:26:54.335 ACCN SIPL 0 receive 357 from 1.3.6.29:5060
2273 10/01 14:26:54.336 ACCN SIPL 0 not found header for Date
2273 10/01 14:26:54.336 ACCN SIPL 0 not found header for Allow-Events
2273 10/01 14:26:54.336 ACCN SIPL 0 -------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 1.3.6.129:5060
From: "Cisco SIP Channel5" ;tag=5bed1e99-272


To: ;tag=EFCE8-E51
Date: Fri, 01 Mar 2002 00:16:22 GMT
Call-ID: c91b8616-270@1.3.6.129:5060
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 51 INVITE
Allow-Events: telephone-event
Content-Length: 0

In the traces shown in Example 21-55, Cisco CME sends a 1 "80 Ringing" message to Cisco UE, indicating that the call terminated on a valid MWI DN and that the MWI request is being processed.

Example 21-55. MWI Call Goes to Alerting State and Disconnects

cue#trace ccn stacksip dbug
cue#show trace buffer tail
SIP/2.0 180 Ringing 
Via: SIP/2.0/UDP 1.3.6.129:5060
From: "Cisco SIP Channel5" ;tag=5bed1e99-272
To: ;tag=EFCE8-E51
Date: Fri, 01 Mar 2002 00:16:22 GMT
Call-ID: c91b8616-270@1.3.6.129:5060
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 51 INVITE
Allow: UPDATE
Allow-Events: telephone-event
Contact: 
Content-Length: 0

.........
CANCEL sip:22225010@1.3.6.29;user=phone SIP/2.0 
Via: SIP/2.0/UDP 1.3.6.129:5060
From: :"Cisco SIP Channel5" ;tag=5bed1e99-272
To: 
Call-ID: c91b8616-270@1.3.6.129:5060
CSeq: 51 CANCEL
Max-Forwards: 50
Content-Length: 0

At this point, Cisco UE has finished notifying Cisco CME about a change in MWI status. It is now the responsibility of the Cisco CME call control software to complete the MWI notification to the IP phone to turn the lamp on or off. To troubleshoot this portion of the transaction, turn on the debug ephone mwi or debug ephone detail traces in Cisco IOS software. The traces in Example 21-56 show the SCCP messages sent by Cisco CME to the phone(s) for turning MWI on and off.

Example 21-56. SIP Outcall from Cisco UE Results in an SCCP MWI Message to the IP Phone

ccme#debug ephone state
ccme#debug ephone mwi
............
Jun 11 05:51:57.663: calling [private] called [22225010] 
Jun 11 05:51:57.663: SkinnyTryCall to 5010 instance 1 start at 0SkinnyTryCall to
 5010 instance 1 match DN 1
Jun 11 05:51:57.663: Phone 0 DN 1 MWI on 0 messages
Jun 11 05:51:57.667: ephone-1[1]:Set MWI line 1 to ON count 0 
Jun 11 05:51:57.667: ephone-1[1]:Set MWI line 0 to ON count 0
Jun 11 05:51:57.667: UpdateCallState DN 10 chan 1 operating in mode 1
Jun 11 05:52:01.874: ephone-1[1]:ONHOOK (internal)
Jun 11 05:52:01.874: ephone-1[1]:call clean up this DN 1 chan 1 was calling other
 DN -1 chan 1
Jun 11 05:52:01.874: this ephone-1 other ephone-(-1) other DN state UNKNOWN
Jun 11 05:52:01.878: ephone-1[1]:CloseReceive
Jun 11 05:52:01.878: ephone-1[1]:StopMedia
Jun 11 05:52:01.878: DN 1 chan 1 End Voice_Mode
Jun 11 05:52:01.878: ephone-1[1]:SetCallState line 1 DN 1 chan 1 ref 13 TsOnHook
Jun 11 05:52:01.882: ephone-1[1]:SpeakerPhoneOnHook
Jun 11 05:52:01.886: ephone-1[1]:SpeakerPhoneOnHook

Troubleshooting Voice Mail VPIM Networking