Archive for the ‘Unity/Unity Connection’ Category

I came across an interesting scenario few days back where customer added a CUC Secondary server back to the Cluster but it was not working as it should.

Customer had two CUC servers in the cluster in a load-balanced configuration with half of the ports on unity-02(sub) and other half on unity-01(Pub). For some hardware failure the secondary failed and they had to re-build it from Scratch. The problem they were facing was that unity was not taking any calls as the first 80 ports were on unity-02 and for some reason it was not happy.

I checked the replication status first and found this:

admin:utils dbreplication runtimestate

DB and Replication Services: ALL RUNNING

Cluster Replication State: Replication status command started at: 2012-10-18-11-44
Replication status command COMPLETED 1 tables checked out of 425
Processing Table: typedberrors with 982 records
No Errors or Mismatches found.

Use ‘file view activelog cm/trace/dbl/sdi/ReplicationStatus.2012_10_23_11_44_00.out’ to see the details

DB Version: ccm7_1_2_20000_2
Number of replicated tables: 425

Cluster Detailed View from PUB (2 Servers):

PING                     REPLICATION    REPL.     DBver&                REPL.     REPLICATION SETUP
SERVER-NAME IP ADDRESS        (msec)  RPC?     STATUS                QUEUE TABLES                 LOOP?  (RTMT) & details
———–             ————           ——      —-         ———–             —–       ——-    —–       —————–
UNITY-01                x.x.0.35            0.049     Yes         Connected         0             match   N/A       (2) PUB Setup Completed
unity-02                x.x.0.36             0.254     Yes         Off-Line               N/A       0      N/A        (4) Setup Completed

admin:file view activelog cm/trace/dbl/sdi/ReplicationStatus.2012_10_23_11_44_00.out

SERVER                 ID STATE    STATUS     QUEUE  CONNECTION CHANGED
———————————————————————–
g_unity_01_ccm7_1_2_20000_2    2 Active   Local           0

————————————————-
I can see (4) with Secondary which means not good!

I then found Secondary server complaining about some CDR records. A little search at Cisco and I found a well known defect. Bug Id: CSCta15666 for CUC 7.1.2.20000-140.

– – –

In CDR Define logs (file list activelog /cm/trace/dbl/*)
We got exception in Cdr define
Ignoreable exception occurred will continue. Value:92

In CDR output broadcast logs (file list activelog /cm/trace/dbl/*)
Error 17 while doing cdr check, will cdr deleteTime taken to do cdr check[1.92180991173]

Exception from cdr delete e.value [37] e.msg[Error executing [su -c ‘ulimit -c 0;cdr delete server g_nhbl_vo_cl1fs02_ccm7_1_2_10000_16’ – informix] returned [9472]]

The steps taken to fix this were the following:
– utils dbreplication stop all on publisher
– utils dbreplication dropadmindb on both servers
– utils dbreplication forcedatasyncsub on subscriber
– utils dbreplication reset all
– rebooted the subscriber

After this, the dbreplication was fixed.

Voicemail has been configured properly at Unity connection but when you press the ‘message’ button on the IP phone it just do nothing.

If you come across an issue like this then make sure you have Voicemail service configured under Device > Device Settings > Phone Services.

If it’s not there then you will have to run the following command from CUCM CLI:

admin: run sql insert into telecasterservice (pkid,Name,NameASCII,Description,URLTemplate,tkPhoneService,EnterpriseSubscription,Priority)values(‘ca69f2e4-d088-47f8-acb2-ceea6722272e’,’Voicemail’,’Voicemail’,’Voicemail’,’Application:Cisco/Voicemail’,2,’t’,1)

This is just notes to myself as after downloading the upgrade files for CUCM or Unity or anything else…we all need to follow the same process of combining them and then verifiying the hash value.

Download FCIV.

Download the files as required:

UCS_Install_UCOS_7.1.3.32900-4.sgn.iso_part1of2

UCS_Install_UCOS_7.1.3.32900-4.sgn.iso_part2of2

Run the following command to combine these files into one .iso file

COPY /B C:\UCS_Install_UCOS_7.1.3.32900-4.sgn.iso_part1of2+C:\UCS_Install_UCOS_7.1.3.32900-4.sgn.iso_part2of2 C:\UCSInstall_UCOS_7.1.3.32900-4.sgn.iso

UCSInstall_UCOS_7.1.3.32900-4.sgn.iso

Use a checksum generator to confirm that the MD5 checksum of the reunited file matches the following checksum:

d450666dafbc8f01c111ed0158f748fb

If the values do not match, the reunited file is damaged.

C:\>cd fciv

C:\FCIV>fciv.exe c:\UCSInstall_UCOS_7.1.3.32900-4.sgn.iso
//
// File Checksum Integrity Verifier version 2.05.
//
d450666dafbc8f01c111ed0158f748fb c:\ucsinstall_ucos_7.1.3.32900-4.sgn.iso

C:\FCIV>

Note: Make sure if you are writing it over a CD/DVD then it should be copied as Data and don’t expand it as an image. The file on the CD/DVD should be a .iso file as Call manager only looks for this file.

Now you can run the upgrade process either from OS Admin or CLI. I prefer CLI but any method can be used.

Disable throttle to speed up the process, Throttling prevents call processing degradation during the upgrade but may cause the upgrade to take longer. Throttling gets enabled by default and is necessary if you perform the upgrade during normal business hours.

Upgrade Process from CLI:

First of all disable ios throttle by using command utils iothrottle disable. If it’s not disabled at start, you will be asked during the upgrade as well where you may or may not disable it.

admin:show version active
Active Master Version: 7.1.2.20000-2

Active Version Installed Software Options:
uc-locale-en_GB-7.1.2.0-139.cop
admin:

admin:utils system
utils system boot*
utils system restart
utils system shutdown
utils system switch-version
utils system upgrade*

admin:utils system upg
admin:utils system upgrade ini
admin:utils system upgrade initiate

Warning: Do not close this window without first exiting the upgrade command.

To preserve system stability during upgrades, the system throttles the upgrade process, which may take considerably longer to complete.  If you are performing this upgrade during a maintenance window and want to speed up the upgrade, you can disable throttling.  Additional information is in the Special Upgrade Information section of the release notes.

Would you like to disable I/O throttling (yes/no): yes

Source:

1) Remote Filesystem
2) DVD/CD
q) quit

Please select an option (1 – 2 or “q” ): 1
Directory: \
Server: 10.9.1.3
User Name: cisco
Password: *****
Protocol:

1) sftp
2) ftp
q) quit

Please select an option (1 – 2 or “q” ): 1
Checking for valid upgrades.  Please wait…

Available options and upgrades in “10.9.1.3:\”:

1) UCSInstall_UCOS_7.1.3.32900-4.sgn.iso
q) quit

Please select an option (1 – 1 or “q” ): 1
Accessing the file.  Please wait…

[KDownloaded 2 MB. [KDownloaded 5 MB. [KDownloaded 8 MB. [KDownloaded 11 MB.
[KDownloaded 15 MB. [KDownloaded 18 MB.[KDownloaded 21 MB.[KDownloaded 24 MB.
[KDownloaded 27 MB.[KDownloaded 31 MB.[KDownloaded 34 MB.[KDownloaded 37 MB.
[KDownloaded 40 MB.[KDownloaded 43 MB.[KDownloaded 45 MB.[KDownloaded 48 MB.

.

.

KDownloaded 3206 MB.[KDownloaded 3209 MB.[KDownloaded 3211 MB.[KDownloaded 3214 MB.
[KDownloaded 3216 MB.[KDownloaded 3219 MB.[KDownloaded 3222 MB.[KDownloaded 3225 MB.
[KDownloaded 3227 MB.[KDownloaded 3230 MB.[KDownloaded 3233 MB.[KDownloaded 3236 MB.

Checksumming the file…

KDownloaded 3236 MB.File validated.

A system reboot is required when the upgrade process completes or is canceled.  This will ensure services affected by the upgrade process are functioning properly.

Downloaded: UCSInstall_UCOS_7.1.3.32900-4.sgn.iso
File version: 7.1.3.32900-4
File checksum: d4:50:66:6d:af:bc:8f:01:c1:11:ed:01:58:f7:48:fb

Automatically switch versions if the upgrade is successful (yes/no): no

Start installation (yes/no): yes
The upgrade log is install_log_2010-08-26.10.41.10.log
Upgrading the system.  Please wait…
08/26/2010 10:41:10 file_list.sh|Starting file_list.sh|<LVL::Info>
08/26/2010 10:41:10 file_list.sh|Parse argument method=sftp|<LVL::Debug>
08/26/2010 10:41:10 file_list.sh|Parse argument source_dir=\|<LVL::Debug>
08/26/2010 10:41:10 file_list.sh|Parse argument dest_file=/var/log/install/downloaded_versions|<LVL::Debug>
08/26/2010 10:41:10 file_list.sh|Parse argument remote_host=10.9.1.3|<LVL::Debug>
08/26/2010 10:41:10 file_list.sh|Parse argument user_name=cisco|<LVL::Debug>
08/26/2010 10:41:10 file_list.sh|Calling SFTP command with metering off|<LVL::Debug>
08/26/2010 10:41:11 file_list.sh|SFTP command complete (0)|<LVL::Debug>
08/26/2010 10:41:11 file_list.sh|List file (pre-filtered):|<LVL::Debug>
08/26/2010 10:41:11 file_list.sh|(CAPTURE) UCSInstall_UCOS_7.1.3.32900-4.sgn.iso|<LVL::Debug>

.

.

08/26/2010 12:18:22 upgrade_install.sh|CSA Status = 0|<LVL::Debug>
08/26/2010 12:18:22 upgrade_install.sh|/etc/init.d/ciscosec start|<LVL::Info>
08/26/2010 12:18:24 upgrade_install.sh|(CAPTURE) Starting ciscosec:  [  OK  ]|<LVL::Debug>
08/26/2010 12:18:24 upgrade_install.sh|IOWAIT monitor stopped|<LVL::Info>
08/26/2010 12:18:24 upgrade_install.sh|0|<LVL::Debug>
08/26/2010 12:18:24 upgrade_install.sh|Upgrade Complete — (0)|<LVL::Info>

Successfully installed UCSInstall_UCOS_7.1.3.32900-4.sgn.iso

The system upgrade was successful.  Please switch versions to activate the upgrade or reboot the system to ensure services affected by the upgrade process are functioning properly.

admin:

admin:

admin:utils system swi
admin:utils system switch-version

Active Master Version: 7.1.2.20000-2

Inactive Master Version: 7.1.3.32900-4

If you are switching to an earlier release, you must run:

utils dbreplication reset all

from the publisher after all the nodes are switched over.

Do you really want to switch between versions ?

Enter (yes/no)? yes

Switching Version and Restarting the Appliance …

Switch version duration can vary depending on the database size
and platform configuration.  Please continue to monitor the
switchover process from here.

Waiting …………………………………………………………………………………………………………………………..

Broadcast message from root (Thu Aug 26 12:30:09 2010):

The system is going down for reboot NOW!

.

Operation succeeded

RESTART NOW!
admin:

After this restart the server@

admin: utils system restart

Once it come  back up, check the services

admin:utils service list

{ The box I was upgrading was a Subscriber so I had to make sure if replication is all f ine }

Pub:

admin:file view activelog cm/trace/dbl/sdi/ReplicationStatus.2010_08_26_15_38_33.out

SERVER                 ID STATE    STATUS     QUEUE  CONNECTION CHANGED
———————————————————————–
g_darcuc_ccm7_1_3_32900_4    2 Active   Local           0
g_goscuc_ccm7_1_3_32900_4    3 Active   Connected       0 Aug 26 15:34:16

————————————————-

No Errors or Mismatches found.
Replication status is good on all available servers.

admin:
admin:
admin:show perf query class “Number of Replicates Created and State of Replication”
==>query class :

– Perf class (Number of Replicates Created and State of Replication) has instances and values:
ReplicateCount  -> Number of Replicates Created   = 427
ReplicateCount  -> Replicate_State                = 2

Sub:

admin:utils dbreplication status

——————– utils dbreplication status ——————–

Replication status check is now running in background.
Use command ‘utils dbreplication runtimestate’ to check its progress

The final output will be in file cm/trace/dbl/sdi/ReplicationStatus.2010_08_26_15_39_17.out

Please use “file view activelog cm/trace/dbl/sdi/ReplicationStatus.2010_08_26_15_39_17.out ” command to see the output
admin:file view activelog cm/trace/dbl/sdi/ReplicationStatus.2010_08_26_15_39_17.out

SERVER                 ID STATE    STATUS     QUEUE  CONNECTION CHANGED
———————————————————————–
g_darcuc_ccm7_1_3_32900_4    2 Active   Connected       0 Aug 26 15:34:16
g_goscuc_ccm7_1_3_32900_4    3 Active   Local           0

————————————————-
No Errors or Mismatches found.
Replication status is good on all available servers.

options: q=quit, n=next, p=prev, b=begin, e=end (lines 1 – 20 of 20) :
admin:
admin:
admin:
admin:show perf query class “Number of Replicates Created and State of Replication”
==>query class :

– Perf class (Number of Replicates Created and State of Replication) has instances and values:
ReplicateCount  -> Number of Replicates Created   = 427
ReplicateCount  -> Replicate_State                = 2

If the count is ‘3’ then you may have replication issues. Follow the steps to resolve replication issues:

  • Utils debreplication stop on Subscriber
  • Utils debreplication stop on Publisher (once you stopped Subscriber)
  • Utils dbreplication reset all (from Publisher)
  • If needed restart Subscriber

This will fix the issue. Sometimes I did came across a misleading message after repairing replication. It was like:

admin:utils dbreplication reset all
Replication reset is in progress. Replication setup will continue in background.
Please watch RTMT replication state on all nodes. It should go from 0 to 2.
When all subs have an RTMT Replicate State of 2, replication setup is complete.
If RTMT Replicate State shows 4, there is an error in replication setup.
DbMon correctly signalled
command failed — Enterprise Replication not active (62)

command failed — Enterprise Replication not active (62)

If you come across this, there is no reason to get panic. It’s a Cisco Bug CSCso82088.

The replication has been successful. You can use the above perf query commands to verify replication status. It should be ‘2’ for good replication.


If replication status still not synches try this:

utils dbreplication stop on sub wait for it to stop.
utils dbreplication stop on pub.

utils dbreplication dropadmindb on pub, wait for syscdr to drop.

utils dbreplication dropadmindb on sub.

Once that is done utils dbreplication reset all from pub.

Another useful command to check replication:

admin:utils dbreplication runtimestate

DB and Replication Services: ALL RUNNING

Cluster Replication State: Only available on the PUB

DB Version: ccm7_1_3_32900_4
Number of replicated tables: 427

Cluster Detailed View from SUB (2 Servers):

PING            REPLICATION     REPL.   DBver&  REPL.   REPLICATION SETUP
SERVER-NAME     IP ADDRESS      (msec)  RPC?    STATUS          QUEUE   TABLES  LOOP?   (RTMT)
———–     ————    ——  —-    ———–     —–   ——- —–   —————–
DAR  172.22.6.x    0.352   Yes     Connected       0       match   N/A     (2)
GOS  172.22.5.x    0.026   Yes     Connected       0       match   N/A     (2)

admin:

To check Database Integrity:

show cuc dbconsistency unitydirdb

show cuc tech dbserver integrity

 

Useful Commands for Cluster:

Show tech network hosts

Show network cluster

Show tech dbstateinfo

utils diagnose test

utils network hosts

utils network host xxxxx – you can put the name of the CCM server which will resolve to ip address. if you put ip address this will give you the name of the server. This will prove that DNS is working correctly.

 

You may come across a situation where you need to reset the password Unity Admin.

You can do it through command prompt:

Microsoft Windows [Version 5.2.3790]

(C) Copyright 1985-2003 Microsoft Corp.

C:\Documents and Settings\Administrator>cd …

C:\Documents and Settings\Administrator>g:

G:\>cd Cisco Unity Connection\TechTools

G:\Cisco Unity Connection\TechTools>pwreset.bat uksupport p36lmn

G:\Cisco Unity Connection\TechTools\pwreset.js(17, 5) Microsoft OLE DB Provider

for SQL Server: The credential matches a previous credential for this user.

G:\Cisco Unity Connection\TechTools>pwreset.bat uksupport Bfnm.lk

G:\Cisco Unity Connection\TechTools\pwreset.js(17, 5) Microsoft OLE DB Provider

for SQL Server: The credential matches a previous credential for this user.

G:\Cisco Unity Connection\TechTools>pwreset.bat uksupport Bfnm.kl@P

Password has been set.

G:\Cisco Unity Connection\TechTools>

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).

The Voicemail for the users was not working. If an external call reaches to their voiceail, they will get a message saying ‘ there is no voicemail box attached to this extension’

I checked the CME configuration for dialpeers etc which looks fine and the Caller getting that message actually means they can get to CUE but then CUE doesn’t recognize that Subscriber or there is no mailbox for that Subscriber.

I checked the configuration for few users at CUE and found all users with proper Voicemail box and everything configured.

To check how the call is flowing myself, I Call-forward all one of the extension and opened the debug iusdn q931 and debug voice dialpeer to check how the call is flowing. Call came in as follows:

Jul  7 16:26:25.294: ISDN BR0/2/1 Q931: RX <- SETUP pd = 8  callref = 0x01

Sending Complete

Bearer Capability i = 0x8090A3
Standard = CCITT
Transfer Capability = Speech
Transfer Mode = Circuit
Transfer Rate = 64 kbit/s
Channel ID i = 0x89
Exclusive, B1
Called Party Number i = 0x81, ‘788552’
Plan:ISDN, Type:Unknown
Jul  7 16:26:25.314: ISDN BR0/2/1 Q931: TX -> CALL_PROC pd = 8  callref = 0x81
Channel ID i = 0x89
Exclusive, B1
Jul  7 16:26:25.354: ISDN BR0/2/1 Q931: TX -> ALERTING pd = 8  callref = 0x81
Progress Ind i = 0x8188 – In-band info or appropriate now available
Jul  7 16:26:37.370: ISDN BR0/2/1 Q931: RX <- DISCONNECT pd = 8  callref = 0x01
Cause i = 0x8090 – Normal call clearing

ephone-dn  1  dual-line
ring internal primary
number 1551 secondary 788552
pickup-group 500
label Joe Bloggs (1552)
description XXXXX788552
name Joe Bloggs
call-forward busy 4000
call-forward noan 4000 timeout 15
corlist incoming User-unrestricted
huntstop channel

From the debugs I found out that the call is coming in to the extension ‘788552’ and then goes to the Voicemail with the same extension.

Here are the debugs – 4000 is the Voicemail Pilot:

Jul 19 12:53:50.525: //-1/xxxxxxxxxxxx/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jul 19 12:53:50.525: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=788552T
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jul 19 12:53:50.525: //-1/xxxxxxxxxxxx/DPM/MatchNextPeer:
Result=Success(0); Incoming Dial-peer=20008 Is Matched
Jul 19 12:53:50.525: //-1/xxxxxxxxxxxx/DPM/dpMatchPeertype:exit@5616
Jul 19 12:53:50.525: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Result=NO_MATCH(-1) After All Match Rules Attempt
Jul 19 12:53:50.525: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeer:exit@6216
Jul 19 12:53:50.529: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
Calling Number=, Called Number=788552, Peer Info Type=DIALPEER_INFO_SPEECH
Jul 19 12:53:50.529: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
Match Rule=DP_MATCH_DEST; Called Number=788552
Jul 19 12:53:50.529: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Dial String=788552, Expanded String=788552, Calling Number=
Timeout=TRUE, Is Incoming=FALSE, Peer Info Type=DIALPEER_INFO_SPEECH
Jul 19 12:53:50.529: //-1/xxxxxxxxxxxx/DPM/MatchNextPeer:
Result=Success(0); Outgoing Dial-peer=20008 Is Matched
Jul 19 12:53:50.529: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
Result=Success(0) after DP_MATCH_DEST
Jul 19 12:53:50.529: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersMoreArg:
Result=SUCCESS(0)
List of Matched Outgoing Dial-peer(s):
1: Dial-peer Tag=20008
Jul 19 12:53:50.529: //-1/8336FB9580EA/DPM/dpMatchPeersCore:
Calling Number=, Called Number=788552, Peer Info Type=DIALPEER_INFO_SPEECH
Jul 19 12:53:50.529: //-1/8336FB9580EA/DPM/dpMatchPeersCore:
Match Rule=DP_MATCH_DEST; Called Number=788552
Jul 19 12:53:50.529: //-1/8336FB9580EA/DPM/dpMatchCore:
Dial String=788552, Expanded String=788552, Calling Number=
Timeout=TRUE, Is Incoming=FALSE, Peer Info Type=DIALPEER_INFO_SPEECH
Jul 19 12:53:50.529: //-1/8336FB9580EA/DPM/MatchNextPeer:
Result=Success(0); Outgoing Dial-peer=20008 Is Matched
Jul 19 12:53:50.529: //-1/8336FB9580EA/DPM/dpMatchPeersCore:
Result=Success(0) after DP_MATCH_DEST
Jul 19 12:53:50.529: //-1/8336FB9580EA/DPM/dpMatchPeersMoreArg:
Result=SUCCESS(0)
List of Matched Outgoing Dial-peer(s):
1: Dial-peer Tag=20008
Jul 19 12:53:50.529: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
Calling Number=, Called Number=4000, Peer Info Type=DIALPEER_INFO_SPEECH
Jul 19 12:53:50.529: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
Match Rule=DP_MATCH_DEST; Called Number=4000
Jul 19 12:53:50.529: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Dial String=4000, Expanded String=4000, Calling Number=
Timeout=TRUE, Is Incoming=FALSE, Peer Info Type=DIALPEER_INFO_SPEECH
Jul 19 12:53:50.529: //-1/xxxxxxxxxxxx/DPM/MatchNextPeer:
Result=Success(0); Outgoing Dial-peer=1000 Is Matched
Jul 19 12:53:50.533: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
Result=Success(0) after DP_MATCH_DEST
Jul 19 12:53:50.533: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersMoreArg:
Result=SUCCESS(0)
List of Matched Outgoing Dial-peer(s):
1: Dial-peer Tag=1000
Jul 19 12:53:50.533: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
Calling Number=, Called Number=4000, Peer Info Type=DIALPEER_INFO_SPEECH
Jul 19 12:53:50.533: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
Match Rule=DP_MATCH_DEST; Called Number=4000
Jul 19 12:53:50.533: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Dial String=4000, Expanded String=4000, Calling Number=
Timeout=FALSE, Is Incoming=FALSE, Peer Info Type=DIALPEER_INFO_SPEECH
Jul 19 12:53:50.533: //-1/xxxxxxxxxxxx/DPM/MatchNextPeer:
Result=Success(0); Outgoing Dial-peer=1000 Is Matched
Jul 19 12:53:50.533: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
Result=Success(0) after DP_MATCH_DEST
Jul 19 12:53:50.533: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersMoreArg:
Result=SUCCESS(0)
List of Matched Outgoing Dial-peer(s):
1: Dial-peer Tag=1000
Jul 19 12:53:50.533: ISDN BR0/2/1 Q931: TX -> CALL_PROC pd = 8  callref = 0x81
Channel ID i = 0x89
Exclusive, B1
Jul 19 12:53:50.537: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
Calling Number=, Called Number=788552, Peer Info Type=DIALPEER_INFO_SPEECH
Jul 19 12:53:50.537: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
Match Rule=DP_MATCH_DEST; Called Number=788552
Jul 19 12:53:50.537: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Dial String=788552, Expanded String=788552, Calling Number=
Timeout=TRUE, Is Incoming=FALSE, Peer Info Type=DIALPEER_INFO_SPEECH
Jul 19 12:53:50.537: //-1/xxxxxxxxxxxx/DPM/MatchNextPeer:
Result=Success(0); Outgoing Dial-peer=20008 Is Matched
Jul 19 12:53:50.537: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
Result=Success(0) after DP_MATCH_DEST
Jul 19 12:53:50.537: //-1/xxxxxxxxxxxx/DPM/dpMatchPeers:
Result=SUCCESS(0)
List of Matched Outgoing Dial-peer(s):
1: Dial-peer Tag=20008
Jul 19 12:53:50.541: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Calling Number=4000, Called Number=, Voice-Interface=0x0,
Timeout=TRUE, Peer Encap Type=ENCAP_VOIP, Peer Search Type=PEER_TYPE_VOICE,
Peer Info Type=DIALPEER_INFO_SPEECH
Jul 19 12:53:50.541: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_ANSWER; Calling Number=4000
Jul 19 12:53:50.541: //-1/xxxxxxxxxxxx/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jul 19 12:53:50.541: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=4000T
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jul 19 12:53:50.541: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Result=-1
Jul 19 12:53:50.541: //-1/xxxxxxxxxxxx/DPM/dpMatchPeertype:exit@5616
Jul 19 12:53:50.541: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Match Rule=DP_MATCH_ORIGINATE; Calling Number=4000
Jul 19 12:53:50.541: //-1/xxxxxxxxxxxx/DPM/dpMatchPeertype:
Is Incoming=TRUE, Number Expansion=FALSE
Jul 19 12:53:50.541: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Dial String=, Expanded String=, Calling Number=4000T
Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH
Jul 19 12:53:50.541: //-1/xxxxxxxxxxxx/DPM/MatchNextPeer:
Result=Success(0); Incoming Dial-peer=1000 Is Matched
Jul 19 12:53:50.541: //-1/xxxxxxxxxxxx/DPM/dpMatchPeertype:exit@5616
Jul 19 12:53:50.541: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
Result=Success(0) after DP_MATCH_ORIGINATE; Incoming Dial-peer=1000
Jul 19 12:53:50.541: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeer:exit@6216
Jul 19 12:53:50.541: //-1/833DB27E8C13/DPM/dpMatchPeersCore:
Calling Number=, Called Number=4000, Peer Info Type=DIALPEER_INFO_SPEECH
Jul 19 12:53:50.541: //-1/833DB27E8C13/DPM/dpMatchPeersCore:
Match Rule=DP_MATCH_DEST; Called Number=4000
Jul 19 12:53:50.541: //-1/833DB27E8C13/DPM/dpMatchCore:
Dial String=4000, Expanded String=4000, Calling Number=
Timeout=TRUE, Is Incoming=FALSE, Peer Info Type=DIALPEER_INFO_SPEECH
Jul 19 12:53:50.545: //-1/833DB27E8C13/DPM/MatchNextPeer:
Result=Success(0); Outgoing Dial-peer=1000 Is Matched
Jul 19 12:53:50.545: //-1/833DB27E8C13/DPM/dpMatchPeersCore:
Result=Success(0) after DP_MATCH_DEST
Jul 19 12:53:50.545: //-1/833DB27E8C13/DPM/dpMatchPeersMoreArg:
Result=SUCCESS(0)
List of Matched Outgoing Dial-peer(s):
1: Dial-peer Tag=1000
Jul 19 12:53:50.589: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
Calling Number=, Called Number=, Peer Info Type=DIALPEER_INFO_SPEECH
Jul 19 12:53:50.589: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
No Outgoing Dial-peer Is Matched; Result=NO_MATCH(-1)
Jul 19 12:53:50.589: //-1/xxxxxxxxxxxx/DPM/dpMatchPeers:
Result=NO_MATCH(-1)
Jul 19 12:53:50.589: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
Calling Number=, Called Number=4000, Peer Info Type=DIALPEER_INFO_SPEECH
Jul 19 12:53:50.589: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
Match Rule=DP_MATCH_DEST; Called Number=4000
Jul 19 12:53:50.593: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Dial String=4000, Expanded String=4000, Calling Number=
Timeout=TRUE, Is Incoming=FALSE, Peer Info Type=DIALPEER_INFO_SPEECH
Jul 19 12:53:50.593: //-1/xxxxxxxxxxxx/DPM/MatchNextPeer:
Result=Success(0); Outgoing Dial-peer=1000 Is Matched
Jul 19 12:53:50.593: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
Result=Success(0) after DP_MATCH_DEST
Jul 19 12:53:50.593: //-1/xxxxxxxxxxxx/DPM/dpMatchPeers:
Result=SUCCESS(0)
List of Matched Outgoing Dial-peer(s):
1: Dial-peer Tag=1000
Jul 19 12:53:50.597: ISDN BR0/2/1 Q931: TX -> ALERTING pd = 8  callref = 0x81
Jul 19 12:53:50.625: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
Calling Number=, Called Number=, Peer Info Type=DIALPEER_INFO_SPEECH

Jul 19 12:53:50.625: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
No Outgoing Dial-peer Is Matched; Result=NO_MATCH(-1)
Jul 19 12:53:50.625: //-1/xxxxxxxxxxxx/DPM/dpMatchPeers:
Result=NO_MATCH(-1)
Jul 19 12:53:50.629: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
Calling Number=, Called Number=4000, Peer Info Type=DIALPEER_INFO_SPEECH
Jul 19 12:53:50.629: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
Match Rule=DP_MATCH_DEST; Called Number=4000
Jul 19 12:53:50.629: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
Dial String=4000, Expanded String=4000, Calling Number=
Timeout=TRUE, Is Incoming=FALSE, Peer Info Type=DIALPEER_INFO_SPEECH
Jul 19 12:53:50.629: //-1/xxxxxxxxxxxx/DPM/MatchNextPeer:
Result=Success(0); Outgoing Dial-peer=1000 Is Matched
Jul 19 12:53:50.629: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
Result=Success(0) after DP_MATCH_DEST
Jul 19 12:53:50.629: //-1/xxxxxxxxxxxx/DPM/dpMatchPeers:
Result=SUCCESS(0)
List of Matched Outgoing Dial-peer(s):
1: Dial-peer Tag=1000
Jul 19 12:53:50.637: ISDN BR0/2/1 Q931: TX -> CONNECT pd = 8  callref = 0x81
Channel ID i = 0x89
Exclusive, B1
Jul 19 12:53:50.713: ISDN BR0/2/1 Q931: RX <- CONNECT_ACK pd = 8  callref = 0x01
Jul 19 12:53:50.713: %ISDN-6-CONNECT: Interface BRI0/2/1:1 is now connected to N/A N/A

Jul 19 12:53:58.649: ISDN BR0/2/1 Q931: RX <- DISCONNECT pd = 8  callref = 0x01
Cause i = 0x8090 – Normal call clearing

So the call was reaching CUE with 788552 but what I found under user settings at CUE that the Primary E.164 number was configured as full DDI instead of ‘788552’.  I  changed that to the 6-digit number and all started working fine.