Scenario#16 – Unity Connection MWI ON/OFF Problem – 7.0(1)

Customer reported an issue with their MWI. They were using Unity connection 7.0(1).

When a new message was left, the MWI light will not come up so there was no way to tell if a new message has arrived. User were logging into their mailboxes to check if there are new messages. Also, if there were more than two new messages and they delete one of them, MWI light was coming up. The issue was intermittent. Sometimes it works fine, sometimes it doesn’t.

I checked the configuration at Call manager which looks fine. The fact that it was intermittent suggested there is no CSS/PT issue. I went into Unity connection servers (they were using two Active/Active UC servers) and re-sync the MWI. It solved the issue for few but not for all. I then decided to investigate the logs of Unity connection server.

For MWI, you need to go into Macro traces and turn on SCCP phone MWI. After doing that I collected traces from RTMT for Connection conversation Manager & Connection Notifier. Going through the traces for a known duration for extension 334, I found below:

/27/2010 11:12:14.713 |14264,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps found result context: ‘(null)’|
07/27/2010 11:12:14.713 |14264,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps found switch objectid: ‘618bf9a6-7fbf-4cb8-87ba-ed03796b6e86’|
07/27/2010 11:12:14.713 |14264,,,Notifier,12,Error getting value of named property MsgID for Ewan McDonald. HRESULT:80004005|
07/27/2010 11:12:14.713 |14264,,,Notifier,12,CCsMWIDevice::TransferPropertiesToTask found mwi on/off type 1|
07/27/2010 11:12:14.713 |14264,,,Notifier,12,CCsMWIDevice::TransferPropertiesToTask found mwi extension ‘334’|
07/27/2010 11:12:14.713 |14264,,,Notifier,12,CCsMWIDevice::TransferPropertiesToTask found mwi port object id ”|
07/27/2010 11:12:14.713 |14264,,,Notifier,12,CCsMWIDevice::TransferPropertiesToTask found mwi object id ‘a575e681-7481-42fa-b8bd-bdc3a266dbd3’|
07/27/2010 11:12:14.713 |14264,,,Notifier,12,CCsMWIDevice::TransferPropertiesToTask found suspend update flag 0|
07/27/2010 11:12:14.713 |14264,,,Notifier,12,CCsMWIDevice::TransferPropertiesToTask found always update flag 1 (when true will send message counts)|
07/27/2010 11:12:14.713 |14264,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps found urgent voice count: 0|
07/27/2010 11:12:14.713 |14264,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps found urgent fax count: 0|
07/27/2010 11:12:14.713 |14264,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps found saved voice count: -2|
07/27/2010 11:12:14.713 |14264,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps found saved fax count: 0|
07/27/2010 11:12:14.713 |14264,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps found saved urgent voice count: 0|
07/27/2010 11:12:14.713 |14264,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps found saved urgent fax count: 0|
07/27/2010 11:12:14.713 |14264,,,Notifier,12,Queued MWI task=[user=’Ewan McDonald’ extension=’334′ type=RESYNC_MWI_OFF mwiType=0=Port phoneSystem=Cisco Call Manager (618bf9a6-7fbf-4cb8-87ba-ed03796b6e86)]|
07/27/2010 11:12:14.714 |12862,,,Arbiter,13,Port 3=Cisco Call Manager PG1-015 has been reserved|
07/27/2010 11:12:14.714 |14264,,,Notifier,20,Ticket d17e0001 request made for resource -1 (switch=0 caps=4) for Task Ewan McDonald  taskid 29129|
07/27/2010 11:12:14.714 |14264,,,Notifier,20,Ticket d17e0001 pending for requested resource -1|
07/27/2010 11:12:14.714 |12862,,,Notifier,20,Ticket d17e0001 found for requested resource -1|
07/27/2010 11:12:14.714 |12862,,,Notifier,20,Ticket d17e0001 granted for resource 3 (requested -1)|
07/27/2010 11:12:14.714 |12874,,,Notifier,12,Execute MWI port=3 task=[user=’Ewan McDonald’ extension=’334′ type=RESYNC_MWI_OFF mwiType=0=Port phoneSystem=Cisco Call Manager (618bf9a6-7fbf-4cb8-87ba-ed03796b6e86)]|
07/27/2010 11:12:14.715 |12874,,,Arbiter,13,Setting port Cisco Call Manager PG1-015 active=Yes activeRefs=0|
07/27/2010 11:12:14.715 |12874,,,Arbiter,13,Switch 0=Cisco Call Manager portCounts change [portsFree=9 answerPorts=8 answerPortsFree=8] to [portsFree=8 answerPorts=8 answerPortsFree=8]|
07/27/2010 11:12:14.715 |12874,,,Arbiter,13,PerfCounters: port modified [name=’Cisco Call Manager PG1-015′ inService=true active=false deleted=false]->[name=’Cisco Call Manager PG1-015′ inService=true active=true deleted=false]|
07/27/2010 11:12:14.715 |12874,,,Arbiter,13,PerfInterval end eUNITY_PERFCTRPHONESYS_PORTIDLEDURATION ID=’PortIdle-21361154-027d-418b-a857-733120514c90′ instance=” [stopping counter]|
07/27/2010 11:12:14.715 |12874,,,Arbiter,13,PerfInterval start eUNITY_PERFCTRPHONESYSPORT_PORTUSAGEDURATION ID=’PortBusy-21361154-027d-418b-a857-733120514c90′ instance=’Cisco Call Manager PG1-015′ [starting counter]|
07/27/2010 11:12:14.715 |12874,,,Arbiter,13,SetPortActive: port=Cisco Call Manager PG1-015 ID=3 switch=Cisco Call Manager (ID=0) available=No caps=0x7c->Enabled|MWI|Notification |
07/27/2010 11:12:14.715 |12874,,,Arbiter,13,PortActivity, MWI Dial out, Port No: Cisco Call Manager PG1-015, Lines in use: 1, Lines available for taking calls: 8|
07/27/2010 11:12:14.716 |12874,,,MiuGeneral,26,Enter EnterThrottle |
07/27/2010 11:12:14.716 |12874,,,MiuGeneral,26,MWIThrottle: wait for concurrent request completion -> state: numQueuedMinInterval=0 numQueuedMaxConcurrent=1 numInProgress=0 maxConcurrentMwi=4 minMwiInterval=0|
07/27/2010 11:12:14.716 |12874,,,MiuGeneral,26,MWIThrottle: done waiting for concurrent request completion|
07/27/2010 11:12:14.716 |12874,,,MiuGeneral,26,MWIThrottle complete -> state: numQueuedMinInterval=0 numQueuedMaxConcurrent=0 numInProgress=1 maxConcurrentMwi=4 minMwiInterval=0|
07/27/2010 11:12:14.716 |12874,,,MiuGeneral,26,Exit EnterThrottle=0x00000000=S_OK|

Something was not normal. I could see message count in negative.

I decided to jump on Call manager and get some traces from there as well to find out what Call manager did after getting MWI request.

This is what I found in CCM traces.

07/27/2010 11:10:55.964 CCM|MGCPHandler received msg from: 172.22.1.252
NTFY 690173580 *@DARVG01. MGCP 0.1
X: 0
O:
|<CLID::StandAloneCluster><NID::172.22.1.253><CT::2,100,134,1.2080654><IP::172.22.1.252><DEV::><LVL::Significant><MASK::2000>
07/27/2010 11:10:55.965 CCM|<CLID::StandAloneCluster><NID::172.22.1.253><CT::2,100,134,1.2080654><MN::MGCPEndPoint><MV::*><DEV::><LVL::All><MASK::ffff>
07/27/2010 11:10:55.965 CCM|MGCPHandler send msg SUCCESSFULLY to: 172.22.1.252

/27/2010 11:12:14.591 CCM|StationD:    (0042516) KeypadButton KeyPadButton=3(Three).|<CLID::StandAloneCluster><NID::172.22.1.253><CT::2,100,39,1.223562436><IP::172.22.0.47><DEV::SEP001D457DCFFD><LVL::State Transition><MASK::0020>
07/27/2010 11:12:14.678 CCM|CMProcMon – ——Entered Router Verification|<CLID::StandAloneCluster><NID::172.22.1.253><LVL::Arbitrary><MASK::0800>
07/27/2010 11:12:14.678 CCM|CMProcMon – —-Exited Router Verification|<CLID::StandAloneCluster><NID::172.22.1.253><LVL::Arbitrary><MASK::0800>
07/27/2010 11:12:14.741 CCM|StationInit: (0042502) StationMwiNotificationMessage mwiTarget=334 mwiCtrl=88997 msgsWaiting=0 totalVm(0/-2) priVm(0/0) totalFax(0/0) priFax(0/0)|<CLID::StandAloneCluster><NID::172.22.1.253><CT::2,100,39,1.223562438><IP::172.22.1.251><DEV::CiscoUM1-VI15><LVL::State Transition><MASK::0020>
07/27/2010 11:12:14.741 CCM|StationD:    (0042502) TX StationMwiResponse: mwiTarget=334 result=3.|<CLID::StandAloneCluster><NID::172.22.1.253><CT::2,100,39,1.223562438><IP::172.22.1.251><DEV::CiscoUM1-VI15><LVL::Detailed><MASK::0800>
07/27/2010 11:12:14.741 CCM|StationD:    (0042502) StationMwiNotification is rejected due to invalid msg count.|<CLID::StandAloneCluster><NID::172.22.1.253><CT::2,100,39,1.223562438><IP::172.22.1.251><DEV::CiscoUM1-VI15><LVL::Significant><MASK::0800>

Confirmed from Call manager traces that message count is indeed in negative which call manager is rejecting saying ‘invalid message count’.

I dig deep to find out the Unity connection famous Bugs:

– CSCsy17809 : Message count may go negative if same message deleted simultaneously

– CSCtc32553 : unity connection 7.x negative mailbox size diagnostics

Symptom:

When a message is accessed and deleted at the exact same time in more than one place, the current message count may drop below zero. Therefore a new message left may not light MWI (until enough new messages exist for the message count to be greater than zero again).

Bug Link:

http://tinyurl.com/33q5msr

A temporary workaround is to run the following command from Unity connection CLI (Admin rights)

"run cuc dbquery unitymbxdb1 execute procedure csp_MailboxesRefreshSize()"

A permanent fix is to upgrade to CUC 7.1(3).