Unity Connection 8.5(1)ES34 Prompt Delays on Sub.

anthony.lotito_2 · ‎04-05-2011

I am noticing a 4 to 6 sec delay between prompts when calls are handled on the Subscriber server that is in a different data center as the Pub. Seems when the Connection sub retrives message counts or when a user presses * to go back to the previous menu the delays happen.

Below is a Port Status Log showing a 4 sec Delay from when I logged into my mailbox and the system played the SayHello_WithShortCut prompt.

My round trip time between the two data centers is 28ms.

Port Status Log

03:41:12, New Call, CalledId=6666, RedirectingId=, Origin=16, Reason=1, CallGuid=08A949A532234D47AA0DA070846E83F5, CallerName=2003406, LastRedirectingId=,

LastRedirectingReason=1024, PortDisplayName=CUCM-Cluster1-1-001,[Origin=Invalid],[Reason=Invalid]

03:41:12, AttemptSignIn

03:41:12, State - AttemptSignIn.cde!Dummy

03:41:12, Event is [NULL]

03:41:12, SubSignIn

03:41:12, Subscriber Sign-In

03:41:12, State - SubSignIn.cde!AnswerPhone

03:41:12, Event is [TrueEvent]

03:41:12, State - SubSignIn.cde!AuthenticateUser

03:41:12, -->SubAuthenticate

03:41:12, State - SubAuthenticate.cde!TryCounter

03:41:12, Event is [NULL]

03:41:12, State - SubAuthenticate.cde!GatherID

03:41:12, Event is [FalseEvent]

03:41:12, State - SubAuthenticate.cde!LoadSubscriberMinimalData

03:41:12, Event is [NULL]

03:41:12, State - SubAuthenticate.cde!GatherPIN

03:41:12, -->SubAuthenticatePW

03:41:12, State - SubAuthenticatePW.cde!ValidatePwd

03:41:17, Subscriber sign-in successful. Alias - 2003406. Extension - 2003406. Caller Id - 2003406.

03:41:18, Event is [TrueEvent]

03:41:18, State - SubAuthenticatePW.cde!ReturnAuthenticated

03:41:18, Event is [Authenticated]

03:41:18, <--SubAuthenticatePW

03:41:18, Event is [Authenticated]

03:41:18, State - SubAuthenticate.cde!ReturnAuthenticated

03:41:18, Event is [Authenticated]

03:41:18, <--SubAuthenticate

03:41:18, Event is [Authenticated]

03:41:18, State - SubSignIn.cde!RunSignInUtil

03:41:18, -->SubSignInUtil

03:41:18, State - SubSignInUtil.cde!CheckAccountLocked

03:41:18, Event is [FalseEvent]

03:41:18, State - SubSignInUtil.cde!CheckExpiredAndNew

03:41:18, Event is [NULL]

03:41:18, State - SubSignInUtil.cde!CheckForExpirationWarning

03:41:18, Event is [NULL]

03:41:18, <--SubSignInUtil

03:41:18, Event is [NULL]

03:41:18, State - SubSignIn.cde!RunSignInUtil_default

03:41:18, Event is [NULL]

03:41:18, State - SubSignIn.cde!RunNextConv

03:41:18, -->SubMenu_Alternate_Custom

03:41:18, Subscriber Mailbox (Anthony Lotito)

03:41:18, State - SubMenu.cde!MapTemplate

03:41:18, Event is [NULL]

03:41:18, State - SubMenu_Alternate_Custom.cde!SetSubConversations

03:41:18, Event is [NULL]

03:41:18, State - SubMenu.cde!RunSubMessageBookmark

03:41:18, -->SubMsgBookmark

03:41:18, State - SubMsgBookmark.cde!CheckForMsgBookmark

03:41:18, Event is [FalseEvent]

03:41:18, <--SubMsgBookmark

03:41:18, Event is [FalseEvent]

03:41:18, State - SubMenu.cde!RunAddAlternateExtensions

03:41:18, -->AddAlternateExtensions

03:41:18, State -

AddAlternateExtensions.cde!CheckAlternateExtensionAddEnabled

03:41:18, Event is [FalseEvent]

03:41:18, <--AddAlternateExtensions

03:41:18, Event is [FalseEvent]

03:41:18, State - SubMenu.cde!CheckAlternateGreeting

03:41:18, Event is [FalseEvent]

03:41:18, State - SubMenu.cde!CheckForSignInOverGreeting

03:41:18, Event is [FalseEvent]

03:41:18, State - SubMenu.cde!RunMsgCount

03:41:18, -->SubMsgCount_Alternate_Custom

03:41:18, State - SubMsgCount.cde!CountMailboxMessages

03:41:22, Event is [NULL]

03:41:22, State - SubMsgCount.cde!GetMailboxStatus

03:41:22, Event is [YesEvent]

03:41:22, State - SubMsgCount.cde!SayHello_WithShortCut

03:41:24, Event is [NULL]

03:41:25, State - SubMsgCount.cde!RunCheckBroadcastMsg_WithShortCut

03:41:25, -->SubBroadcastMessage

03:41:25, State - SubBroadcastMessage.cde!CheckForBroadcastMessage

03:41:25, Event is [NULL]

03:41:25, <--SubBroadcastMessage

03:41:25, Event is [NULL]

03:41:25, State - SubMsgCount.cde!AnnounceMsgCount

03:41:28, Event is [HangupEvent]

03:41:28, <--SubMsgCount_Alternate_Custom

03:41:28, Event is [HangupEvent]

03:41:28, <--SubMenu_Alternate_Custom

03:41:28, Event is [HangupEvent]

03:41:28, Idle

Any ideas as to why the delay? I don't experience any delay when the Pub is taking calls.

Bradford Magnani · ‎04-05-2011

Hi Anthony,

It sounds similar to the behavior noted in http://tools.cisco.com/Support/BugToolKit/search/getBugDetails.do?method=fetchBugDetails&bugId=CSCth21949&from=summary

Try making the subcriber "Primary" status in the cluster (fail it over) and then see if the delay then occurs when calls are taken by the publisher. Regardless, you'll probably want to get a TAC case open to take a look. This isn't an issue with ping times, it's more likely an Informix database delay you're seeing.

Hope that helps,

Brad

anthony.lotito_2 · ‎04-06-2011

Brad,

Durning the installation there was a DNS error and I ignored it at the time (shame on me). I then went into the CLI and added back the DNS servers once the install completed.

My TAC case is 617305837.

I made the Subscriber the Primary in the Cluster and the delay is no longer there.

I am hoping this can be corrected by by modifying the /etc/nsswitch.conf file as you indicated in the BUG ID.

Any chance of you picking up this SR?

08:59:18, New Call, CalledId=11181, RedirectingId=, Origin=16, Reason=1, CallGuid=99D0AA71387C4FA3BE68B428A7C9EBFB, CallerName=Anthony Lotito, LastRedirectingId=, LastRedirectingReason=1024, PortDisplayName=CUCM-Cluster1-1-001,[Origin=Invalid],[Reason=Invalid]
08:59:18, AttemptSignIn
08:59:18, State - AttemptSignIn.cde!Dummy
08:59:18, Event is [NULL]
08:59:18, SubSignIn
08:59:18, Subscriber Sign-In
08:59:18, State - SubSignIn.cde!AnswerPhone
08:59:18, Event is [TrueEvent]
08:59:18, State - SubSignIn.cde!AuthenticateUser
08:59:18, -->SubAuthenticate
08:59:18,         State - SubAuthenticate.cde!TryCounter
08:59:18,         Event is [NULL]
08:59:18,         State - SubAuthenticate.cde!GatherID
08:59:18,         Event is [FalseEvent]
08:59:18,         State - SubAuthenticate.cde!LoadSubscriberMinimalData
08:59:18,         Event is [NULL]
08:59:18,         State - SubAuthenticate.cde!GatherPIN
08:59:18,         -->SubAuthenticatePW
08:59:18,                 State - SubAuthenticatePW.cde!ValidatePwd
08:59:23,                 Subscriber sign-in successful. Alias - 2003406. Extension - 2003406. Caller Id - 2003406.
08:59:23,                 Event is [TrueEvent]
08:59:23,                 State - SubAuthenticatePW.cde!ReturnAuthenticated
08:59:23,                 Event is [Authenticated]
08:59:23,         <--SubAuthenticatePW
08:59:23,         Event is [Authenticated]
08:59:23,         State - SubAuthenticate.cde!ReturnAuthenticated
08:59:23,         Event is [Authenticated]
08:59:23, <--SubAuthenticate
08:59:23, Event is [Authenticated]
08:59:23, State - SubSignIn.cde!RunSignInUtil
08:59:23, -->SubSignInUtil
08:59:23,         State - SubSignInUtil.cde!CheckAccountLocked
08:59:23,         Event is [FalseEvent]
08:59:23,         State - SubSignInUtil.cde!CheckExpiredAndNew
08:59:23,         Event is [NULL]
08:59:23,         State - SubSignInUtil.cde!CheckForExpirationWarning
08:59:23,         Event is [NULL]
08:59:23, <--SubSignInUtil
08:59:23, Event is [NULL]
08:59:23, State - SubSignIn.cde!RunSignInUtil_default
08:59:23, Event is [NULL]
08:59:23, State - SubSignIn.cde!RunNextConv
08:59:23, -->SubMenu_Alternate_Custom
08:59:23,         Subscriber Mailbox (Anthony Lotito)
08:59:23,         State - SubMenu.cde!MapTemplate
08:59:23,         Event is [NULL]
08:59:23,         State - SubMenu_Alternate_Custom.cde!SetSubConversations
08:59:23,         Event is [NULL]
08:59:23,         State - SubMenu.cde!RunSubMessageBookmark
08:59:23,         -->SubMsgBookmark
08:59:23,                 State - SubMsgBookmark.cde!CheckForMsgBookmark
08:59:23,                 Event is [FalseEvent]
08:59:23,         <--SubMsgBookmark
08:59:23,         Event is [FalseEvent]
08:59:23,         State - SubMenu.cde!RunAddAlternateExtensions
08:59:23,         -->AddAlternateExtensions
08:59:23,                 State - AddAlternateExtensions.cde!CheckAlternateExtensionAddEnabled
08:59:23,                 Event is [FalseEvent]
08:59:23,         <--AddAlternateExtensions
08:59:23,         Event is [FalseEvent]
08:59:23,         State - SubMenu.cde!CheckAlternateGreeting
08:59:23,         Event is [FalseEvent]
08:59:23,         State - SubMenu.cde!CheckForSignInOverGreeting
08:59:23,         Event is [FalseEvent]
08:59:23,         State - SubMenu.cde!RunMsgCount
08:59:23,         -->SubMsgCount_Alternate_Custom
08:59:23,                 State - SubMsgCount.cde!CountMailboxMessages
08:59:23,                 Event is [NULL]
08:59:23,                 State - SubMsgCount.cde!GetMailboxStatus
08:59:23,                 Event is [YesEvent]
08:59:23,                 State - SubMsgCount.cde!SayHello_WithShortCut
08:59:25,                 Event is [NULL]
08:59:26,                 State - SubMsgCount.cde!RunCheckBroadcastMsg_WithShortCut
08:59:26,                 -->SubBroadcastMessage
08:59:26,                         State - SubBroadcastMessage.cde!CheckForBroadcastMessage
08:59:26,                         Event is [NULL]
08:59:26,                 <--SubBroadcastMessage
08:59:26,                 Event is [NULL]
08:59:26,                 State - SubMsgCount.cde!AnnounceMsgCount
08:59:29,                 Event is [TimeoutEvent]
08:59:29,         <--SubMsgCount_Alternate_Custom
08:59:29,         Event is [TimeoutEvent]
08:59:29,         State - SubMenu.cde!CheckMailStoreMounted
08:59:29,         Event is [FalseEvent]
08:59:29,         State - SubMenu.cde!CheckJumpToNewMessages
08:59:29,         Event is [FalseEvent]
08:59:29,         State - SubMenu.cde!AnnounceMenu
08:59:32,         Event is [TT3Event]
08:59:32,         State - SubMenu.cde!GetMailStoreInfo
08:59:32,         Event is [UMSS_EVENT]
08:59:32,         State - SubMenu.cde!CheckDelItemMenu
08:59:32,         Event is [TrueEvent]
08:59:32,         State - SubMenu.cde!OldMessageMenu
08:59:33,         Event is [TT1Event]
08:59:34,         State - SubMenu.cde!RunOldMsgStack
08:59:34,         -->SubOldMsgStack
08:59:34,                 State - SubOldMsgStack.cde!SetFolderInProps
08:59:34,                 Event is [NULL]
08:59:34,                 State - SubOldMsgStack.cde!AnnounceMsgs
08:59:35,                 Event is [NULL]
08:59:35,                 State - SubOldMsgStack.cde!CheckTotalMsgCount
08:59:35,                 Event is [NULL]
08:59:35,                 State - SubNewMsgStack.cde!CheckOfferMsgTypeMenu
08:59:35,                 Event is [FalseEvent]
08:59:35,                 State - SubNewMsgStack.cde!PlayMsgStack
08:59:35,                 -->SubMsgPlay_Alternate_Custom
08:59:35,                         State - SubMsgPlay_Custom.cde!MapTemplate
08:59:35,                         Event is [NULL]
08:59:35,                         State - SubMsgPlay.cde!MsgRoot
08:59:35,                         Event is [NULL]
08:59:35,                         State - SubMsgPlay.cde!ValidMsgStreams
08:59:35,                         Event is [NULL]
08:59:35,                         State - SubMsgPlay.cde!MessageHeaderDispatchCheck
08:59:35,                         Event is [NULL]
08:59:35,                         State - SubMsgPlay.cde!MessageHeader
08:59:37,                         Event is [TimeoutEvent]
08:59:37,                         State - SubMsgPlay.cde!MessageBody
08:59:38,                         Event is [HangupEvent]
08:59:38,                         State - SubMsgPlay.cde!SetExitProperties_Hangup
08:59:38,                         Event is [NULL]
08:59:38,                         State - SubMsgPlay.cde!MessageExit_CheckMarkNew
08:59:38,                         Event is [FalseEvent]
08:59:38,                         State - SubMsgPlay.cde!MessageExit_CheckMarkRead
08:59:38,                         Event is [TrueEvent]
08:59:39,                         State - SubMsgPlay.cde!MessageExit_MarkRead
08:59:39,                         Event is [TrueEvent]
08:59:39,                         State - SubMsgPlay.cde!MessageExit_CheckToggleUrgency
08:59:39,                         Event is [FalseEvent]
08:59:39,                         State - SubMsgPlay.cde!MessageExit_CheckUndelete
08:59:39,                         Event is [FalseEvent]
08:59:39,                         State - SubMsgPlay.cde!MessageExit_RouteToAction
08:59:39,                         Event is [ExitHangup]
08:59:39,                         State - SubMsgPlay.cde!PushHangup
08:59:39,                         Event is [HangupEvent]
08:59:39,                 <--SubMsgPlay_Alternate_Custom
08:59:39,                 Event is [HangupEvent]
08:59:39,         <--SubOldMsgStack
08:59:39,         Event is [HangupEvent]
08:59:39, <--SubMenu_Alternate_Custom
08:59:39, Event is [HangupEvent]
08:59:39, Idle

yavuzsab · ‎04-15-2012

Hi Anthony, We are facing the exact same symptom with 4 to 6 sec delays with prompt being played as you have described for my customer on CUC 8.5(1) Pub and Sub over WAN between datacentre on UCS. Did the workaround for that bug rectify your issue? please advise the outcome. Thank you, Yavuz

Craig Cooper · ‎04-15-2012

G'day Yavuz!

I believe the issue ended up being CSCtn78617. Log a case with the TAC if you need an 8.6(2) ES build ( the latest of which include the fix for CSCtn78617).

Kind regards,

Craig

yavuzsab · ‎04-16-2012

Will do Craig. Thank you for your support as always mate.

Your definitely the go to person for UC!!

Thanks again.

Cheers!

Yavuz

Sent from my iPhone