MWI Traces – SCCP Integration (CUC and CUCM brief analisys)

Luis Gomez · ‎12-26-2016

MWI Traces – SCCP Integration

Traces to Enable:

CUCM: Call Manager traces

CUC: Notifier - Conversation Manager

Test Call Information – New Message Event

User Display name: Luis Gomez

User Extension: 8801

MWI ON: 9099

MWI Off: 9098

Time Stamp of Call: around 10:32am

On Notifier Traces, we do a Search for the User Display Name

If it's a New Message event you can include in the search the line "NOTIFYQ_ACTION_MSG_NEW" to be more specific. (for a message deleted you can use "NOTIFYQ_ACTION_MSG_DELETED" to search for)

On Notepad++ we can use "Regular Expressions" to do a search for:

NOTIFYQ_ACTION_MSG_NEW.*Luis Gomez

From CUC Notifier logs:

New Message event:

10:32:37.192 |2805,,,Notifier,21,MessageStoreMonitor NOTIFYQ_ACTION_MSG_NEW Luis Gomez MailboxObjectId=70d01488-cfab-421d-8b5c-9fced9f8f1bb VoiceNormal-Prioritycd7ddebe-22bc-4ed3-9ae7-c4afea74b01a

10:32:37.192 |2805,,,Notifier,21,Luis Gomez: Processing NewMsgEvent MsgId=cd7ddebe-22bc-4ed3-9ae7-c4afea74b01a

Adjust Message count:

10:32:37.192 |2805,,,Notifier,24,Luis Gomez: Adjust message counts by 1 for media=Voice priority=Normal-Priority dispatch=false starting 0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0

10:32:37.192 |2805,,,Notifier,24,Luis Gomez: Adjusted message counts for media=Voice priority=Normal-Priority dispatch=false now 0,1,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0

Check MWI, Mailbox count is 1 but MWI is OFF so it needs an update:

10:32:37.192 |2805,,,Notifier,12,Luis Gomez, mwi extension=8801: needs MWI update with (Voice+Fax+Text) mail count= 1 and MWI state=OFF

10:32:37.192 |2805,,,Notifier,12,Luis Gomez: evaluate MWI - lamp update to ON mwi extension=8801

From Conversation Manager logs:

MWI request enter in Queue:

10:32:37.193 |14506,,,Notifier,12,Queued MWI task=[user='Luis Gomez' extension='8801' type=MWI_ON mwiType=0=Port phoneSystem=PS-SCCP-11.5 (b7c7e0e9-e561-41d2-892f-dc2c4a493720)]

10:32:37.194 |14506,,,Notifier,0,MWI ON Requested: Name=Luis Gomez DTMFID=8801 #NewMsgs=0

Received Taskid and Ticket number:

10:32:37.194 |14506,,,Notifier,4,InsertTask Luis Gomez taskid 6

10:32:37.194 |14506,,,Notifier,20,Ticket 60001 request made for resource -1 (switch=2 caps=4) for Task Luis Gomez taskid 6

Ticket is pending while VM port is reserved, then ticket is assigned to port and proceed:

10:32:37.194 |14506,,,Notifier,20,Ticket 60001 pending for requested resource -1

10:32:37.195 |14494,,,Arbiter,13,Port 6=PG-SCCP-231-004 has been reserved

10:32:37.195 |14494,,,Notifier,20,Ticket 60001 found for requested resource -1

10:32:37.195 |14494,,,Notifier,20,Ticket 60001 granted for resource 6 (requested -1)

10:32:37.195 |27303,,,Notifier,3,DoTask starting with threadid 0x00006aa7 for Luis Gomez taskid 6, ticket 60001

MWI is executed:

10:32:37.195 |27303,,,Notifier,12,Execute MWI port=6 task=[user='Luis Gomez' extension='8801' type=MWI_ON mwiType=0=Port phoneSystem=PS-SCCP-11.5 (b7c7e0e9-e561-41d2-892f-dc2c4a493720)]

in this case, Port 004 has been assigned, following "MiuSkinny" events we can see the communication between CUC and CUCM:

10:32:37.238 |27303,,,MiuMethods,17,Enter CMiuSkinnyLine::SetMWI

10:32:37.238 |27303,PG-SCCP-231-004,,MiuSkinny,24,SetMWI destAddress='8801' mwiOn=true sendMsgCount=false msgCounts=[VoiceSeenAll=0 VoiceSeenUrg=0 VoiceUnseenAll=0 VoiceUnseenUrg=0 FaxSeenAll=0 FaxSeenUrg=0 FaxUnseenAll=0 FaxUnseenUrg=0])

State is "Initiate MWI":

10:32:37.242 |27303,PG-SCCP-231-004,,MiuSkinny,24,CAvSkinnyCallStatus::SetState New=<Initiate MWI> Old=<Idle> PreviousOld=<Wait For Close Call>)

CUC send the message "StationMwiNotificationMessage" with user ext target and MWI number target:

10:32:37.242 |27303,PG-SCCP-231-004,,MiuSkinny,13,Send StationMwiNotificationMessage (92 bytes) mwiTargetNumber="8801" mwiControlNumber="9099" areMessagesWaiting=1 normalVmCounts.numNewMsgs=4294967295 normalVmCounts.numOldMsgs=4294967295 priorityVmCounts.numNewMsgs=4294967295 priorityVmCounts.numOldMsgs=4294967295 normalFaxCounts.numNewMsgs=4294967295 normalFaxCounts.numOldMsgs=4294967295 priorityFaxCounts.numNewMsgs=4294967295 priorityFaxCounts.numOldMsgs=4294967295

CUCM response with a Result code 0, MWI OK

10:32:37.247 |14244,PG-SCCP-231-004,,MiuSkinny,12,Receive [Header prefix: length=36 version=18] StationMwiResponseMessage (36 bytes) mwiTargetNumber="8801" resultCode=0=MwiOk

Set state back to Idle and exit:

10:32:37.247 |14244,PG-SCCP-231-004,,MiuSkinny,24,CAvSkinnyCallStatus::SetState New=<Idle> Old=<Wait For Enhanced MWI Response> PreviousOld=<Initiate MWI>)

Port is disconnected:

10:32:37.249 |27303,,,Arbiter,13,PortActivity, Call Disconnect, Port No: PG-SCCP-231-004, Lines in use: 0, Lines available for taking calls: 12

MWI task is marked as Completed, taskid is deleted:

10:32:37.249 |27303,,,Notifier,12,Completed MWI task=[user='Luis Gomez' extension='8801' type=MWI_ON mwiType=0=Port phoneSystem=PS-SCCP-11.5 (b7c7e0e9-e561-41d2-892f-dc2c4a493720)]

10:32:37.249 |27303,,,Notifier,0,MWI ON Completed: Name=Luis Gomez DTMFID=8801 #NewMsgs=0

10:32:37.249 |27303,,,Notifier,3,DoTask finished with threadid 0x00006aa7 for Luis Gomez taskid 6, ticket 60001

10:32:37.250 |27303,,,Notifier,4,Deleting Task Luis Gomez taskid 6

Back in Notifier Logs

The MWI results is marked a Completed successfully as well:

10:32:37.250 |2806,,,Notifier,21,ResultMonitor NOTIFYQ_ACTION_MWION_COMPLETE Luis Gomez MailboxObjectId=70d01488-cfab-421d-8b5c-9fced9f8f1bb 2e0d86da-7d89-49a6-b048-d2bd5b162e0f

10:32:37.257 |2806,,,Notifier,12,Luis Gomez: MWI (ON) completed successfully for mwi extension =8801

From CUCM traces

From CUCM logs we can do a search for the "StationMwiNotificationMessage" event, this is sent by CUC on a MiuSkinny message and it's seeing on CM as well, we can also find on the same line the MWI target and MWI control number:

05447678.001 |10:32:37.242 |AppInfo |StationInit: (0000167) StationMwiNotificationMessage mwiTarget=8801 mwiCtrl=9099 msgsWaiting=1 totalVm(-1/-1) priVm(-1/-1) totalFax(-1/-1) priFax(-1/-1)

Then there's a process named "MessageWaitingManager", it checked the PT and CSS, right here CUCM send the response message back to CUC:

05447681.001 |10:32:37.242 |AppInfo |MessageWaitingManager::ssInforeq mwiOnOffDn=9099 passedCSS=fe620ab1-5f41-7527-835e-1e2661e76a94 mwiDnCss=fe620ab1-5f41-7527-835e-1e2661e76a94 numQueued=0

05447682.001 |10:32:37.243 |AppInfo |MessageWaiting::sendDaReq dialingPattern=8801 dialingPartition=16c63caf-1cc0-fdba-e932-da71211df904 voiceMailbox= orig digitString=8801, cmDeviceType 0

MWI response, result = 0

05447683.001 |10:32:37.243 |AppInfo |StationD: (0000167) TX StationMwiResponse: mwiTarget=8801 result=0.

At this point, CUCM have received the MWI request from CUC and have sent the response, now all the responsibility lies on the CUCM to turn ON the light on the IP phone.

Execute procedure, Set MWI

05447685.001 |10:32:37.243 |AppInfo |DB: SQL1[execute procedure dblSetMWIEx('8801', '16c63caf-1cc0-fdba-e932-da71211df904', 2, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0)]

05447687.001 |10:32:37.434 |AppInfo |LineControl(152): -sendToCdpcByCi-, sigName=CcInfoReq, CI=0 without crp

05447687.002 |10:32:37.434 |AppInfo |LineControl(152): -dispatchToAllDevices-, sigName=CcInfoReq, device=SEP001819F5936E

Lamp mode = 2

05447690.001 |10:32:37.434 |AppInfo |StationD: (0000140) SetLamp mode=2, stim=15 stimInst=0.

Display prompt (you have one new message):

05447691.001 |10:32:37.434 |AppInfo |StationD: (0000140) DisplayPromptStatus timeOut=0 Status='�$' content='You have voice mail' line=0 CI=0 ver=85720016.

On SIP integration the sequence doesn't change that much, the MiuSkinny events are replaced by SIP messages where CUC sent a SIP Notify with a "Message Waiting : Yes/No" event and the same is processed by CUCM the same way checking the CSS and PT first, we should see a 200 OK from CUCM for that event, any other event will results on a MWI failure.

I hope you can find this document useful for your MWI trace analysis.

Best regards,

Luis Gomez

luisgom@cisco.com