User interaction with the Unity Connection TUI (and VUI) can be thought of as a set of conversations, where each conversation consists of a set of states and transitions. We move from one conversation state to the next based on touch tone (DTMF) input from the user or as the result of actions that take place behind the scene by the conversation engine (e.g. validating a password).
For example, when a user logs in to Connection he starts in the SubSignIn conversation where the TUI prompts the user to enter his password. After successfully logging in, we move on to the SubMenu conversation which presents the main subscriber menu “To play new messages, press 1. To send a message, press 2…”
Within each conversation we move from one conversation state to the next. Conversation states do things like play prompts and collect touch tones from the user. They also process information, like checking a subscriber’s configuration settings, or run other conversations. The event queue contains events that tell the various conversation states what to do next. The event at the front of the event queue tells the current state which state to go to next. Events get placed on the event queue when users press touch tones, or when the conversation needs to transition to another state based on the result of some action, like checking a configuration setting.
For example suppose a subscriber has logged in, and is now at the AnnouceMenu state in the SubMenu conversation. The AnnounceMenu state plays the main subscriber menu “To play new messages, press 1. To send a message, press 2…” and collects touch tone input from the user. The user presses 2, so we push a TT2Event (touch tone 2 event) on the event queue, which causes the AnnounceMenu state to transition to the GetMailboxStatus state. The GetMailboxStatus state checks to see if the subscriber’s mailbox is full or is approaching the size limit. The subscriber’s mailbox size is not over the limit or approaching the limit, so GetMailboxStatus pushes a YES_EVENT on the queue, and we transition to the CheckStreamlinedSend state. The CheckStreamlinedSend state checks to see if the subscriber is configured to use the Streamlined Send conversation or the Standard Send conversation. In this case, the subscriber is configured to use the Streamlined Send conversation (the default), so the CheckStreamlinedSend state pushes a TRUE_EVENT on the queue, and we transition to the RunStreamlinedSend state. The RunStreamlinedSend state runs the Streamlined Send conversation.
While the StreamlinedSend conversation is running the SubMenu conversation is essentially paused at the RunStreamlinedSend state. We transition from state to state within the StreamlinedSend conversation, and we may even run additional conversations from within the StreamlinedSend conversation, but eventually we will return to the RunStreamlinedSend state in the SubMenu conversation. Then we will transition to the next state in the SubMenu conversation based on the event that is on the event queue when we return.
The Connection Port Status Monitor is a useful tool for following the flow of the conversations and their states and transitions in real time. It is also a useful tool for learning how the Unity Connection conversations work. It is available at: http://www.ciscounitytools.com/WEAK.htm. The example output from the port status monitor below shows the shows the state transitions described above:
10:37:13, State - SubMenu.cde!AnnounceMenu
10:37:18, Event is [TT2Event]
10:37:18, State - SubMenu.cde!GetMailboxStatus
10:37:18, Event is [YesEvent]
10:37:18, State - SubMenu.cde!CheckStreamlinedSend
10:37:18, Event is [TrueEvent]
10:37:18, State - SubMenu.cde!RunStreamlinedSend
10:37:18, -->StreamlinedSend
10:37:18, State - StreamlinedSend.cde!Init
10:37:18, Event is [NULL]
10:37:18, State - StreamlinedSend.cde!CheckAddressFirst
10:37:18, Event is [FalseEvent]
10:37:18, State - StreamlinedSend.cde!PreRecord
When tracking down conversation problems turn on all CDE, ConvSub, and
PhraseServer micro traces. The sections
below describe some of the more useful traces, but be sure to turn them all
on! Also, be aware that when setting
macro traces, any previously set micro traces will be changed.
When gathering the trace files in the RTMT, choose the Connection Conversation
Manager.
When troubleshooting the Unity Connection conversation, if you can determine the state in which a problem occurred, you will be close to pinpointing the problem. Also being able to find the state transitions in the log can help you determine what a subscriber was doing when a problem occurred.
The CDE state machine micro trace (10) logs the entry to and exit from each conversation state and the event that triggered the transition from one state to the next. A typical diagnostic looks like the following:
05/22/2007 10:37:36.796 |4976,Default Switch-1-001,4827C2899032400AAB008788A285D714,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/SubMenu.cde!CheckStreamlinedSend] [Src/CsStateMachine.cpp:187]|
It contains the following information:
The date and time: 05/22/2007 10:37:36.796
The thread ID: 4976
The port: Default Switch-1-001
The GUID of the call: 4827C2899032400AAB008788A285D714
The micro trace: CDE
The trace level: 10
The diagnostic information: CCsStateMachine::Execute : Next
state is [/opt/cisco/connection/share/tui/SubMenu.cde!CheckStreamlinedSend]
[Src/CsStateMachine.cpp:187]
Each call has a unique GUID. Since a log file can contain traces for multiple calls that occurred simultaneously, it will be easier to follow the flow of a single call by filtering out all of the others. You can do this by finding all of the lines in the log file that contain the GUID you’re interested in or a certain port with a pattern matching tool like grep.
The following line shows that we called the OnEntry method for the ValidatePwd state in the SubSignIn conversation. The path to the conversation script file and the name of the current state are separated by an exclamation point (/opt/Cisco/connection/share/tui/SubSignIn.cde!ValidatePwd).
05/22/2007 09:00:45.025 |4976,Default Switch-1-001,20C9CF44973D4566B1C835FACC4E07F9,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/SubSignIn.cde!ValidatePwd] [Src/CsStateMachine.cpp:138]
The next line shows that we exited the OnEntry method of the ValidatePwd state with a return value of S_OK. Usually when we exit from a state’s OnEntry method we are done with that state. Some states have an OnExit method that is executed before moving on to the next state. So sometimes you’ll see information about a state’s OnExit method too.
05/22/2007 09:00:47.541 |4976,Default Switch-1-001,20C9CF44973D4566B1C835FACC4E07F9,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/SubSignIn.cde!ValidatePwd] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]
The next line shows that the next event on the event queue is a LockedEvent:
05/22/2007 09:00:47.541 |4976,Default Switch-1-001,20C9CF44973D4566B1C835FACC4E07F9,CDE,10,CCsStateMachine::Execute : Event is [LockedEvent] [Src/CsStateMachine.cpp:165]
The last line shows that the next state we will enter is the LockedAccount state in the SubSignIn conversation. This line and the line above tell us that we are transitioning to the LockedAccount state as a result of the LockedEvent state on the event queue.
05/22/2007 09:00:47.549 |4976,Default Switch-1-001,20C9CF44973D4566B1C835FACC4E07F9,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/SubSignIn.cde!LockedAccount] [Src/CsStateMachine.cpp:187]
This next section shows how to use the conversation traces to troubleshoot some specific problems with symptoms that appear in the Unity Connection conversation.
When an outside caller attempts to leave a message for a subscriber, if the outside caller hears the subscriber’s greeting followed by “You can not record a message for <subscriber>. This mailbox is full.” It probably means the Connection server is low on disk space. If the subscriber’s mailbox was full, Connection would still allow outside callers to leave messages for this subscriber. The following trace, logged during the PHGreeting conversation in the PlayGreeting state, confirms that the server is low on disk space:
05/29/2007 13:46:48.598 |25057,Default Switch-1-001,51B02B3916F94FE58A5CE588D47966F7,ConvSub,-1,SendOutsideCallerMessage: CCsCmlSession::CreateDraftMessage(AUDIO) failed, hr=0x80046424 E_CML_LOCAL_STORE_OVERFLOW, pDraftMessage=(nil) [Src/PHGreeting.cpp:1307]
If you see this trace in the log file after Connection has entered the PlayGreeting state:
05/29/2007 13:46:37.854 |25057,Default Switch-1-001,51B02B3916F94FE58A5CE588D47966F7,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/PHGreeting.cde!PlayGreeting] [Src/CsStateMachine.cpp:138]
and before exiting the PlayGreeting state:
05/29/2007 13:46:55.222 |25057,Default Switch-1-001,51B02B3916F94FE58A5CE588D47966F7,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/PHGreeting.cde!PlayGreeting] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]
and all three traces have the same GUID, then you know that it was logged during the PlayGreeting state in the PHGreeting conversation.
When the server is low on disk space subscribers attempting to send subscriber to subscriber messages will hear “The system is currently unable to record. Please try again later.”
You can set the percentage of disk space that can be in use before Connection stops taking messages on the Disk Capacity page in the SA, under System Settings/Advanced/Disk Capacity. By default this is set to 95%, so these errors probably mean that there are too many messages on the server.
Suppose a site has set up a simple call handler that asks the user to enter an extension or press 1 to return to the opening greeting. When callers reach this call handler and dial certain extensions, they hear “I did not recognize that as a valid extension,” but when they call other extensions the call handler transfers the call successfully.
When Connection plays a call handler’s greeting it is in the PlayGreeting state in the PHGreeting conversation, just like when it plays a subscriber’s greeting. This brings up an important point. Each subscriber has its own call handler. So whenever Connection plays a greeting in the PHGreeting state, it is playing a call handler’s greeting. To differentiate between a subscriber’s call handler and a system call handler, we call a subscriber’s call handler a primary call handler. By looking at the diagnostic traces you can tell if Connection is playing a subscriber’s greeting or a call handler’s greeting by finding a diagnostic that indicates whether the call hander is a primary call handler, or not.
05/29/2007 15:57:07.118 |32306,Default Switch-1-001,E33DEE5D20734BEEB25E288DCF297E9A,ConvSub,5,GetCallHandlerProperties: IS_PRIMARY=[FALSE] [Src/PHGreeting.cpp:3058]
Another useful piece of information is the call handler’s alias. If the call handler is a primary call handler, its alias will be the same as its associated subscriber’s alias. If it is a system call hander, its alias will be the call handler’s display name.
05/29/2007 15:57:07.118 |32306,Default Switch-1-001,E33DEE5D20734BEEB25E288DCF297E9A,ConvSub,5,GetCallHandlerProperties: ALIAS=[Call Handler 1] [Src/PHGreeting.cpp:3059]
Once we have located the traces that indicate that we’re in the PHGreeting state, and we are playing the greeting of the call handler that we’re interested in, then we can try to determine why Connection is failing to transfer calls to certain extensions. After skipping past a bunch of traces, we see:
05/29/2007 15:57:10.286 |32306,Default Switch-1-001,E33DEE5D20734BEEB25E288DCF297E9A,ConvSub,5,GatherDigits: DTMF received [1] [Src/PHGreeting.cpp:2277]
05/29/2007 15:57:10.287 |32306,Default Switch-1-001,E33DEE5D20734BEEB25E288DCF297E9A,ConvSub,5,GatherDigits: Matched one-key [1] [Src/PHGreeting.cpp:2304]|
05/29/2007 15:57:10.287 |32306,Default Switch-1-001,E33DEE5D20734BEEB25E288DCF297E9A,ConvSub,5,GatherDigits: Digit [1] locked [Src/PHGreeting.cpp:2333]
The trace that tells us that digit 1 is locked is suspicious. When a digit is locked it means to ignore additional input. This is configured in the Caller Input page for that digit in the SA. Since this call handler is configured to return to the opening greeting when the user presses 1 and the 1 key is locked, transfers to extensions beginning with 1 will fail, or the caller may be transferred to the wrong extension. For example, if a caller entered 1001 at the call handler’s greeting, the caller would be transferred to the opening greeting immediately. The call handler will not wait for additional digits, because the 1 key is locked. Then the opening greeting would receive the digits 001, which in most configurations would be an invalid extension. The caller would not hear any of the opening greeting unless he entered the digits 1001 very slowly.
The following diagnostic, located a few lines after the ones above indicates that the call handler took the action specified for a key:
05/29/2007 15:57:10.287 |32306,Default Switch-1-001,E33DEE5D20734BEEB25E288DCF297E9A,ConvSub,5,ProcessUserInput: Take Action for Menu Entry Index=[3]! [Src/PHGreeting.cpp:2821]
Menu entry index 3 corresponds to the 1 key. However the index isn’t what’s really important here. What is important is the diagnostic above that shows that we matched the one-key action for the 1, and that we are taking an action on it. When a caller enters an extension during a call handler’s greeting, you will always see the diagnostic that shows that we matched a one-key action (Matched one-key [n]), but if you don’t see that diagnostic that shows that we took an action, then we just collected the digit (as part of an extension).
When a call is transferred successfully from a call handler, you will see traces like the following:
05/30/2007 10:27:49.437 |32306,Default Switch-1-001,0CD5F7F2B4B849F2A458E293D90E7F0D,ConvSub,5,GatherDigits: DTMF received [2] [Src/PHGreeting.cpp:2277]|
05/30/2007 10:27:49.437 |32306,Default Switch-1-001,0CD5F7F2B4B849F2A458E293D90E7F0D,ConvSub,5,GatherDigits: Matched one-key [2] [Src/PHGreeting.cpp:2304]|
... [traces omitted]
05/30/2007 10:27:49.437 |32306,Default Switch-1-001,0CD5F7F2B4B849F2A458E293D90E7F0D,ConvSub,5,GatherDigits: Gathering additional digits... [Src/PHGreeting.cpp:2372]|
05/30/2007 10:27:51.777 |32306,Default Switch-1-001,0CD5F7F2B4B849F2A458E293D90E7F0D,ConvSub,1,GatherDigits: GatherDigits() returned 0x00045b35 S_MIU_TERM_TIMEOUT, digits=[001], num=[3] [Src/PHGreeting.cpp:2382]|
05/30/2007 10:27:51.777 |32306,Default Switch-1-001,0CD5F7F2B4B849F2A458E293D90E7F0D,ConvSub,5,GatherDigits: Adding digits - digits gathered so far are [2001] [Src/PHGreeting.cpp:2408]|
As you can see from the traces above, when the transfer is successful, we still log the diagnostic that shows that we matched a one-key action (Matched one-key [2]). But after that you can see that we collected more digits, and there is no diagnostic showing that we took an action.
If a key is locked and it does not have an action associated with it, it is ignored. For example, if the 1 key was locked, and it was not configured to perform any action, callers who dial an extension beginning with a 1 will either get the wrong extension, or they will hear “I did not recognize that as a valid extension,” just like in the previous example. In this case, you would see something like the following in the logs:
06/04/2007 09:03:59.541 |32305,Default Switch-1-001,5B2528060FE5420490DAC6D44C03E774,ConvSub,1,PlayGreeting_OnEntry: Ignoring digits [1] [Src/PHGreeting.cpp:3957]
... [traces omitted]
06/04/2007 09:04:02.149 |32305,Default Switch-1-001,5B2528060FE5420490DAC6D44C03E774,ConvSub,5,GatherDigits: DTMF received [0] [Src/PHGreeting.cpp:2277]
06/04/2007 09:04:02.149 |32305,Default Switch-1-001,5B2528060FE5420490DAC6D44C03E774,ConvSub,5,GatherDigits: Matched one-key [0] [Src/PHGreeting.cpp:2304]
... [traces omitted]
06/04/2007 09:04:04.088 |32305,Default Switch-1-001,5B2528060FE5420490DAC6D44C03E774,ConvSub,5,GatherDigits: Adding digits - digits gathered so far are [001] [Src/PHGreeting.cpp:2408]
In this case, the caller dialed the extension 1001. The first diagnostic tell us that the call handler is ignoring the 1. Then we see a diagnostic that tell us that we got a 0, and the last diagnostic tells us that we gathered the digits 001. The caller will hear “I did not recognize that as a valid extension” if 001 is not a valid extension. Otherwise he will be transferred to extension 001, although he dialed 1001.