12-26-2016 12:25 PM - edited 03-12-2019 10:25 AM
MWI Traces – SCCP Integration
Traces to Enable:
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
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
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
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 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)
05447679.000 |10:32:37.242 |SdlSig |StationMwiNotification |restart0 |StationD(1,100,64,167) |StationInit(1,100,63,1) |1,100,14,1328.28821^192.168.217.232^UMLab-1-VI4 |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] mwiTargetDn=8801 mwiControlDn=9099 msgsWaiting=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.000 |10:32:37.243 |SdlSig |DbVoiceMailUpdtReq |initialized |Db(1,100,211,1) |MessageWaiting(1,100,135,143) |1,100,14,1328.28821^192.168.217.232^UMLab-1-VI4 |[T:N-H:0,N:0,L:0,V:0,Z:0,D:0] 02000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 d815c8eb 709a9fe7 00000000
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.000 |10:32:37.434 |SdlSig |StationOutputSetLamp |restart0 |StationD(1,100,64,140) |StationD(1,100,64,140) |1,100,42,1.1651^*^* |[R:N-H:0,N:1,L:0,V:0,Z:0,D:0] StimulusName=VoiceMail Mode=LampOn Instance=0
05447690.001 |10:32:37.434 |AppInfo |StationD: (0000140) SetLamp mode=2, stim=15 stimInst=0.
Display prompt (you have one new message):
05447691.000 |10:32:37.434 |SdlSig |StationOutputDisplayPromptStatus |restart0 |StationD(1,100,64,140) |StationD(1,100,64,140) |1,100,42,1.1651^*^* |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] TimeOut=0 Status=�$ UnicodeStatus= Line=0 CI=0
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
Find answers to your questions by entering keywords or phrases in the Search bar above. New here? Use these resources to familiarize yourself with the community: