*******************************************************************************

Incoming call transferred…no traces

 

 

Shows an incoming call from extension 1001 to voice mail port 8000, as well as GUID of this call for later reference

05/24/2007 11:00:23.126 |18553,Default Switch-1-001,B17AFD9741BE4AC8BD362ECBEB03B710,Arbiter,-1,Incoming Call: Caller=1001, Called=8000, Redirect=, Reason=1, Port=Default Switch-1-001, PortsInUse=1, AnsPortsFree=1, CallGuid=B17AFD9741BE4AC8BD362ECBEB03B710|

Shows call being transferred to extension 1000 (destAddr). The transfer is a release transfer.

05/24/2007 11:00:28.458 |18553,Default Switch-1-001,B17AFD9741BE4AC8BD362ECBEB03B710,MiuGeneral,25,Enter CAvMiuCall::TransferEx destAddr='1000' type=2=Release maxRings=4 mediaSwitch=''|

The transfer completed successfully (S_OK)

05/24/2007 11:00:29.658 |18553,Default Switch-1-001,,MiuGeneral,25,Exit CAvMiuCall::TransferEx=0x00000000=S_OK|

 

*******************************************************************************

Incoming call, failed login…no traces

Shows an incoming call from extension 1001 to voice mail port 8000, as well as GUID of this call for later reference

05/24/2007 13:07:22.137 |18552,Default Switch-1-001,B3518AFE5FA243BF813D4FF4139EC086,Arbiter,-1,Incoming Call: Caller=1001, Called=8000, Redirect=, Reason=1, Port=Default Switch-1-001, PortsInUse=1, AnsPortsFree=1, CallGuid=B3518AFE5FA243BF813D4FF4139EC086|

Shows failure to authenticate user potter.

05/24/2007 13:07:26.757 |18552,Default Switch-1-001,B3518AFE5FA243BF813D4FF4139EC086,CDL,11,CCsCdlSubscriber::Authenticate: Cannot authenticate user: potter IMS Result Code: 1 on line 1693 of file src/CsCdlSubscriber.cpp: Error: 0x80046505 Description: E_CDL_SP_EXEC_FAILURE|

Shows the reason for the failed authentication – invalid password

05/24/2007 13:07:26.758 |18552,Default Switch-1-001,B3518AFE5FA243BF813D4FF4139EC086,-1,-1,An invalid password entered when trying to log into a subscriber mailbox. Details - potter [123].|

Shows a second failure to authenticate user potter.

05/24/2007 13:07:29.188 |18552,Default Switch-1-001,B3518AFE5FA243BF813D4FF4139EC086,CDL,11,CCsCdlSubscriber::Authenticate: Cannot authenticate user: potter IMS Result Code: 1 on line 1693 of file src/CsCdlSubscriber.cpp: Error: 0x80046505 Description: E_CDL_SP_EXEC_FAILURE|

Shows the reason for the second failed authentication – invalid password again

05/24/2007 13:07:29.188 |18552,Default Switch-1-001,B3518AFE5FA243BF813D4FF4139EC086,-1,-1,An invalid password entered when trying to log into a subscriber mailbox. Details - potter [123].|

Shows that the user account potter, ID 123, has been locked due to exceeding the maximum number of failed login attempts.

05/24/2007 13:07:32.669 |18552,Default Switch-1-001,B3518AFE5FA243BF813D4FF4139EC086,-1,-1,A subscriber account has been locked as max number of invalid login attempts exceeded. Details - potter [123].|

 

 

*******************************************************************************

Incoming call transfer…CDE State machine trace ON

Shows an incoming call from extension 1001 to voice mail port 8000, as well as GUID of this call for later reference

05/25/2007 08:35:06.584 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,Arbiter,-1,Incoming Call: Caller=1001, Called=8000, Redirect=, Reason=1, Port=Default Switch-1-001, PortsInUse=1, AnsPortsFree=1, CallGuid=257B7B2DA71A4831B9ED1CCA55DF1A66|

Shows the beginning of the conversation state machine executing with the first state being Dummy in AttemptSignIn.cde.  This is the state machine for the AttemptSignIn conversation – each conversation has its own state machine.

05/25/2007 08:35:06.862 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Starting state machine with root state [/opt/cisco/connection/share/tui/AttemptSignIn.cde!Dummy] [Src/CsStateMachine.cpp:126]|

Shows the OnEntry method of the Dummy state beginning

05/25/2007 08:35:06.862 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/AttemptSignIn.cde!Dummy] [Src/CsStateMachine.cpp:138]|

Shows the OnEntry method of the Dummy state ending and returning S_OK.

05/25/2007 08:35:06.881 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/AttemptSignIn.cde!Dummy] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]|

Shows the event that will drive the next state transition – in this case NULL or no event.

05/25/2007 08:35:06.881 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Event is [NULL] [Src/CsStateMachine.cpp:165]|

Shows that the next state will be NULL, meaning the conversation is finished and will be exited.

05/25/2007 08:35:06.881 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Next state is [NULL] [Src/CsStateMachine.cpp:187]|

Shows the state machine exiting for AttemptSignIn

05/25/2007 08:35:06.881 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Exiting state machine. [Src/CsStateMachine.cpp:223]|

Shows the beginning of the conversation state machine executing with the first state being CheckRoutingRuleXfer in PHTransfer.cde.  This is the state machine for the PHTransfer conversation.

05/25/2007 08:35:06.954 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Starting state machine with root state [/opt/cisco/connection/share/tui/PHTransfer.cde!CheckRoutingRuleXfer] [Src/CsStateMachine.cpp:126]|

Shows the beginning of the first state in the PHTransfer conversation. Following this line are lines that show each state’s entry and exit.  Only different or particularly interesting traces will be annotated for a while.

05/25/2007 08:35:06.954 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!CheckRoutingRuleXfer] [Src/CsStateMachine.cpp:138]|

05/25/2007 08:35:06.955 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!CheckRoutingRuleXfer] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]|

05/25/2007 08:35:06.955 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Event is [NULL] [Src/CsStateMachine.cpp:165]|

05/25/2007 08:35:06.955 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/PHTransfer.cde!LoadInfo] [Src/CsStateMachine.cpp:187]|

05/25/2007 08:35:06.955 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!LoadInfo] [Src/CsStateMachine.cpp:138]|

Shows that the state LoadInfo is a backend, or custom, state, meaning it is backend code in libConvSub.so that will be executed. 

05/25/2007 08:35:06.955 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10, : CCustomState::OnEntry : State name=[LoadInfo] onentry=[LoadInfo_OnEntry] library=[libConvSub.so] [Src/CustomState.cpp:162]|

05/25/2007 08:35:07.054 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!LoadInfo] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]|

Shows the event that will drive the next state transition – in this case a TrueEvent – the LoadInfo state generated a TrueEvent in backend code.

05/25/2007 08:35:07.054 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Event is [TrueEvent] [Src/CsStateMachine.cpp:165]|

05/25/2007 08:35:07.055 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Next state is [NULL] [Src/CsStateMachine.cpp:187]|

05/25/2007 08:35:07.055 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Exiting state machine. [Src/CsStateMachine.cpp:223]|

Shows the beginning of the state machine for PHGreeting.cde. 

05/25/2007 08:35:07.064 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Starting state machine with root state [/opt/cisco/connection/share/tui/PHGreeting.cde!PlayGreeting] [Src/CsStateMachine.cpp:126]|

05/25/2007 08:35:07.064 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/PHGreeting.cde!PlayGreeting] [Src/CsStateMachine.cpp:138]|

05/25/2007 08:35:07.064 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10, : CCustomState::OnEntry : State name=[PlayGreeting] onentry=[PlayGreeting_OnEntry] library=[libConvSub.so] [Src/CustomState.cpp:162]|

05/25/2007 08:35:10.473 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/PHGreeting.cde!PlayGreeting] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]|

05/25/2007 08:35:10.473 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Event is [NULL] [Src/CsStateMachine.cpp:165]|

05/25/2007 08:35:10.473 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Next state is [NULL] [Src/CsStateMachine.cpp:187]|

05/25/2007 08:35:10.473 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10, : CCustomState::OnExit : State name=[PlayGreeting] onexit=[PlayGreeting_OnExit] library=[libConvSub.so] [Src/CustomState.cpp:263]|

05/25/2007 08:35:10.474 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Exiting state machine. [Src/CsStateMachine.cpp:223]|

Shows the beginning of the state machine for PHTransfer.cde. 

05/25/2007 08:35:10.474 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Starting state machine with root state [/opt/cisco/connection/share/tui/PHTransfer.cde!CheckRoutingRuleXfer] [Src/CsStateMachine.cpp:126]|

05/25/2007 08:35:10.474 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!CheckRoutingRuleXfer] [Src/CsStateMachine.cpp:138]|

05/25/2007 08:35:10.474 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!CheckRoutingRuleXfer] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]|

05/25/2007 08:35:10.475 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Event is [NULL] [Src/CsStateMachine.cpp:165]|

05/25/2007 08:35:10.475 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/PHTransfer.cde!LoadInfo] [Src/CsStateMachine.cpp:187]|

05/25/2007 08:35:10.475 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!LoadInfo] [Src/CsStateMachine.cpp:138]|

05/25/2007 08:35:10.475 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10, : CCustomState::OnEntry : State name=[LoadInfo] onentry=[LoadInfo_OnEntry] library=[libConvSub.so] [Src/CustomState.cpp:162]|

05/25/2007 08:35:10.500 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!LoadInfo] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]|

05/25/2007 08:35:10.500 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Event is [FalseEvent] [Src/CsStateMachine.cpp:165]|

05/25/2007 08:35:10.500 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/PHTransfer.cde!CheckPlayTransferIntro] [Src/CsStateMachine.cpp:187]|

05/25/2007 08:35:10.500 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!CheckPlayTransferIntro] [Src/CsStateMachine.cpp:138]|

05/25/2007 08:35:10.512 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!CheckPlayTransferIntro] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]|

05/25/2007 08:35:10.512 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Event is [TrueEvent] [Src/CsStateMachine.cpp:165]|

05/25/2007 08:35:10.512 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/PHTransfer.cde!PlayTransferIntro] [Src/CsStateMachine.cpp:187]|

05/25/2007 08:35:10.513 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!PlayTransferIntro] [Src/CsStateMachine.cpp:138]|

05/25/2007 08:35:12.640 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!PlayTransferIntro] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]|

05/25/2007 08:35:12.640 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Event is [NULL] [Src/CsStateMachine.cpp:165]|

05/25/2007 08:35:12.640 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/PHTransfer.cde!XferCall] [Src/CsStateMachine.cpp:187]|

05/25/2007 08:35:12.640 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!XferCall] [Src/CsStateMachine.cpp:138]|

05/25/2007 08:35:12.640 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,CDE,10, : CCustomState::OnEntry : State name=[XferCall] onentry=[XferCall_OnEntry] library=[libConvSub.so] [Src/CustomState.cpp:162]|

Shows call being transferred to extension 1000 (destAddr). The transfer is a release transfer.

05/25/2007 08:35:12.708 |18553,Default Switch-1-001,257B7B2DA71A4831B9ED1CCA55DF1A66,MiuGeneral,25,Enter CAvMiuCall::TransferEx destAddr='1000' type=2=Release maxRings=4 mediaSwitch=''|

05/25/2007 08:35:14.261 |18553,Default Switch-1-001,,MiuGeneral,25,Exit CAvMiuCall::TransferEx=0x00000000=S_OK|

05/25/2007 08:35:14.261 |18553,Default Switch-1-001,,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!XferCall] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]|

Shows a HangupEvent.  This means the caller disconnected or the transfer was completed.  The HangupEvent will typically cause the system to complete the call.  The following traces show the call winding down through cleanup states until the call is eventually completed.

05/25/2007 08:35:14.261 |18553,Default Switch-1-001,,CDE,10,CCsStateMachine::Execute : Event is [HangupEvent] [Src/CsStateMachine.cpp:165]|

05/25/2007 08:35:14.261 |18553,Default Switch-1-001,,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/PHTransfer.cde!DoHangUp] [Src/CsStateMachine.cpp:187]|

05/25/2007 08:35:14.261 |18553,Default Switch-1-001,,CDE,10, : CCustomState::OnExit : State name=[XferCall] onexit=[XferCall_OnExit] library=[libConvSub.so] [Src/CustomState.cpp:263]|

05/25/2007 08:35:14.262 |18553,Default Switch-1-001,,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!DoHangUp] [Src/CsStateMachine.cpp:138]|

05/25/2007 08:35:14.262 |18553,Default Switch-1-001,,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!DoHangUp] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]|

05/25/2007 08:35:14.262 |18553,Default Switch-1-001,,CDE,10,CCsStateMachine::Execute : Event is [HangupEvent] [Src/CsStateMachine.cpp:165]|

05/25/2007 08:35:14.262 |18553,Default Switch-1-001,,CDE,10,CCsStateMachine::Execute : Next state is [NULL] [Src/CsStateMachine.cpp:187]|

05/25/2007 08:35:14.262 |18553,Default Switch-1-001,,CDE,10,CCsStateMachine::Execute : Exiting state machine. [Src/CsStateMachine.cpp:223

 

 

*******************************************************************************

Incoming call transfer with the following traces on:

CDE

·          03 – Security

·          04 – State Machine Trace

·          14 – Errors

·          16 – Call Progress Diags

ConvSub

·          00 – Method entry/exit

·          01 – General method returns, parameter values

·          02 – Data access

·          03 – Named properties access

·          04 – MIU access

·          05 – Call progress

PhraseServer

·          03 – Information

·          05 – Phrase IDs

·          06 – Prompt file names, and audio stream info

·          07 – DTMF input

 

Shows an incoming call from extension 1001 to voice mail port 8000, as well as GUID of this call for later reference

05/25/2007 09:39:05.230 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,Arbiter,-1,Incoming Call: Caller=1001, Called=8000, Redirect=, Reason=1, Port=Default Switch-1-001, PortsInUse=1, AnsPortsFree=1, CallGuid=47E796321E084A76AF7745FD623AC089|

05/25/2007 09:39:05.231 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,16,AttemptSignIn : CCsCDEConvBase::Run : Entering conversation [AttemptSignIn] [Src/CsCDEConvBase.cpp:124]|

ConvSub method entry and exit diags show when a backend state is entered and when it is complete.  Anything happening between these two diags is happening in backend conversation code.  See matching Exiting for the method.  Note that one method can call another, so they can be nested within each other, rather than sequential.  Pay attention to the CDE trace about entering a state to see where the backend is entered and exited.

05/25/2007 09:39:05.231 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [AttemptSignIn_RunStart]|

05/25/2007 09:39:05.231 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [GetCallerNumber]|

05/25/2007 09:39:05.231 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,4,GetCallerNumber: ICsMiuCall::get_CallerID() returned 1001 [Src/AttemptSignIn.cpp:107]|

05/25/2007 09:39:05.231 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [GetCallerNumber]|

Notice that the diagnostic includes the name of the backend method (AttemptSignIn_RunStart) and the file and line number – this is useful for debugging.

05/25/2007 09:39:05.231 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,1,AttemptSignIn_RunStart: GetCallerNumber() returned caller ID: 1001 [Src/AttemptSignIn.cpp:145]|

Named properties carry around lots of conversation information.  ConvSub trace 3 shows every time a property is set or read from named props by backend code.  E_NP_PROP_NOT_FOUND means the property was not in named props already – this is not necessarily an error!  It maybe that the property is optional.  Note the property name: SignIn.IsFirstSignIn.

05/25/2007 09:39:05.231 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,AttemptSignIn_RunStart: ICsNamedProps::GetPropBool() could not find property: SignIn.IsFirstSignIn.  GetPropBool() returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/AttemptSignIn.cpp:153]|

05/25/2007 09:39:05.231 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [GetSubscriberByDtmfIdOrPhoneWithAutoLogon]|

05/25/2007 09:39:05.248 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,16,No Subscriber Records found by Dtmf Access Id 1001 0x80046500 (Src/CsCallSession.cpp 217)|

05/25/2007 09:39:05.249 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetSubscriberByDtmfIdOrPhoneWithAutoLogon: CCsCallSession::GetSubscriberByDtmfId() returned NULL [Src/AttemptSignIn.cpp:59]|

05/25/2007 09:39:05.263 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,16,No Subscriber Records found by Phone Number 1001 0x80046500 (Src/CsCallSession.cpp 266)|

05/25/2007 09:39:05.263 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetSubscriberByDtmfIdOrPhoneWithAutoLogon: CCsCallSession::GetSubscriberByPhoneNumberWithAutoLogon() returned NULL [Src/AttemptSignIn.cpp:65]|

05/25/2007 09:39:05.263 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [GetSubscriberByDtmfIdOrPhoneWithAutoLogon]|

05/25/2007 09:39:05.263 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,AttemptSignIn_RunStart: GetSubscriberByDtmfIdOrPhoneWithAutoLogon() could not find a susbcriber matching 1001 [Src/AttemptSignIn.cpp:174]|

05/25/2007 09:39:05.263 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,AttemptSignIn_RunStart: ICsNamedProps::SetPropString(SignInCallerID) to value: 1001 returned 0x00000000 S_OK [Src/AttemptSignIn.cpp:190]|

05/25/2007 09:39:05.263 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,AttemptSignIn_RunStart: ICsNamedProps::SetPropBool(SignIn.IsFirstSignIn) to value: false returned 0x00000000 S_OK [Src/AttemptSignIn.cpp:193]|

ConvSub method entry and exit diags show when a backend state is entered and when it is complete.  This is the matching “exiting” diag to the entry diagnostic above.

05/25/2007 09:39:05.263 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [AttemptSignIn_RunStart]|

05/25/2007 09:39:05.263 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Starting state machine with root state [/opt/cisco/connection/share/tui/AttemptSignIn.cde!Dummy] [Src/CsStateMachine.cpp:126]|

05/25/2007 09:39:05.263 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/AttemptSignIn.cde!Dummy] [Src/CsStateMachine.cpp:138]|

05/25/2007 09:39:05.264 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/AttemptSignIn.cde!Dummy] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]|

05/25/2007 09:39:05.264 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Event is [NULL] [Src/CsStateMachine.cpp:165]|

05/25/2007 09:39:05.264 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Next state is [NULL] [Src/CsStateMachine.cpp:187]|

05/25/2007 09:39:05.264 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Exiting state machine. [Src/CsStateMachine.cpp:223]|

05/25/2007 09:39:05.264 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,16,AttemptSignIn : CCsCDEConvBase::Run : Exiting conversation [AttemptSignIn] [Src/CsCDEConvBase.cpp:390]|

05/25/2007 09:39:05.280 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,16,PHTransfer : CCsCDEConvBase::Run : Entering conversation [PHTransfer] [Src/CsCDEConvBase.cpp:124]|

05/25/2007 09:39:05.280 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [PHTransfer_RunInit]|

05/25/2007 09:39:05.280 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHTransfer_RunInit: ICsNamedProps::GetPropBool() could not find property: bUseDialingDomainXfer.  GetPropBool() returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:287]|

05/25/2007 09:39:05.280 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHTransfer_RunInit: ICsNamedProps::GetPropVariant() found property CurEnt = .  GetPropVariant() returned 0x00000000 [Src/PHTransfer.cpp:302]|

05/25/2007 09:39:05.292 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,16,No Call Handler Dtmf Access Id Records found {fd848904-5dd6-4823-8e04-1afeb62cc709} 0x80046504 (Src/CsCallHandler.cpp 141)|

05/25/2007 09:39:05.302 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,16,No Distribution List Dtmf Access Id Records found {a1acfe54-a664-4b28-b32e-85bec4ec64e5} 0x80046504 (Src/CsCallDistributionList.cpp 91)|

Here’s the call handler being processed by the PHTransfer conversation – Opening Greeting, which happens to be a SECONDARY (rather than primary) call handler.

05/25/2007 09:39:05.302 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,PHTransfer_RunInit: Got call handler [{fd848904-5dd6-4823-8e04-1afeb62cc709} Opening Greeting  SECONDARY]  [Src/PHTransfer.cpp:322]|

05/25/2007 09:39:05.302 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [SetLanguageOnContext]|

05/25/2007 09:39:05.302 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,SetLanguageOnContext: Evaluating language settings: bUseCallLanguage=1, lLang=1033 [Src/PHTransfer.cpp:61]|

There are many chances for the call language to be changed.  These diags shows that language inheritance is in play, and the language of the call is ENU, American English.

05/25/2007 09:39:05.302 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,SetLanguageOnContext: Language inheritance requested, leaving context language as [ENU] [Src/PHTransfer.cpp:96]|

05/25/2007 09:39:05.302 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,SetLanguageOnContext: Setting context language to [ENU] [Src/PHTransfer.cpp:102]|

05/25/2007 09:39:05.302 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [SetLanguageOnContext]|

05/25/2007 09:39:05.302 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [PHTransfer_RunInit]|

05/25/2007 09:39:05.303 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [PHTransfer_RunStart]|

05/25/2007 09:39:05.303 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [ClearSubscriberEnvironment]|

05/25/2007 09:39:05.303 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,ClearSubscriberEnvironment: ICsNamedProps::RemoveProp(PromptSpeed) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/SubSignIn.cpp:2555]|

05/25/2007 09:39:05.303 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,ClearSubscriberEnvironment: ICsNamedProps::RemoveProp(PromptVolume) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/SubSignIn.cpp:2556]|

05/25/2007 09:39:05.303 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [ClearSubscriberEnvironment]|

05/25/2007 09:39:05.303 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [PHTransfer_RunStart]|

05/25/2007 09:39:05.303 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Starting state machine with root state [/opt/cisco/connection/share/tui/PHTransfer.cde!CheckRoutingRuleXfer] [Src/CsStateMachine.cpp:126]|

05/25/2007 09:39:05.303 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!CheckRoutingRuleXfer] [Src/CsStateMachine.cpp:138]|

05/25/2007 09:39:05.303 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!CheckRoutingRuleXfer] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]|

05/25/2007 09:39:05.303 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Event is [NULL] [Src/CsStateMachine.cpp:165]|

05/25/2007 09:39:05.303 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/PHTransfer.cde!LoadInfo] [Src/CsStateMachine.cpp:187]|

05/25/2007 09:39:05.303 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!LoadInfo] [Src/CsStateMachine.cpp:138]|

05/25/2007 09:39:05.303 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10, : CCustomState::OnEntry : State name=[LoadInfo] onentry=[LoadInfo_OnEntry] library=[libConvSub.so] [Src/CustomState.cpp:162]|

05/25/2007 09:39:05.303 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [LoadInfo_OnEntry]|

05/25/2007 09:39:05.303 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,LoadInfo_OnEntry: ICsNamedProps::GetPropBool() could not find property: bUseDialingDomainXfer.  GetPropBool() returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:1243]|

Call transfer is driven by contact rules – the next chunk of diags show the backend determining which contact rule is active.

05/25/2007 09:39:05.303 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [GetActiveContactRule]|

05/25/2007 09:39:05.303 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetActiveContactRule: ICsNamedProps::SetPropString(strDTMFAccessID) to value:  returned 0x00000000 S_OK [Src/PHTransfer.cpp:824]|

05/25/2007 09:39:05.325 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetActiveContactRule: Schedule mode is [0] [Src/PHTransfer.cpp:841]|

05/25/2007 09:39:05.325 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetActiveContactRule: ICsNamedProps::SetPropVariant(varObjectID) to value:  returned 0x00000000 S_OK [Src/PHTransfer.cpp:851]|

05/25/2007 09:39:05.332 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [RuleIsActive]|

05/25/2007 09:39:05.332 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [DateIsUndefined]|

05/25/2007 09:39:05.332 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,1,DateIsUndefined: Checking date [12:00:00 AM 01/01/1972] against undefined values [Src/CUGA.cpp:53]|

05/25/2007 09:39:05.332 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,1,DateIsUndefined: Date [12:00:00 AM 01/01/1972] was found to be a valid, defined date [Src/CUGA.cpp:70]|

05/25/2007 09:39:05.332 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [DateIsUndefined]|

Alternate contact rule is not active (Rule Active = FALSE)

05/25/2007 09:39:05.332 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,RuleIsActive: Is [Alternate] Rule Active = FALSE [Src/PHTransfer.cpp:711]|

05/25/2007 09:39:05.332 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [RuleIsActive]|

05/25/2007 09:39:05.332 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetActiveContactRule: Alternate Transfer Option is not Active! [Src/PHTransfer.cpp:862]|

Standard contact rule is now in play.

05/25/2007 09:39:05.332 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetActiveContactRule: Contact rule being used is [Standard] [Src/PHTransfer.cpp:881]|

05/25/2007 09:39:05.332 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [RuleIsActive]|

05/25/2007 09:39:05.332 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [DateIsUndefined]|

05/25/2007 09:39:05.332 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,1,DateIsUndefined: Checking date [12:00:00 AM 01/00/1900] against undefined values [Src/CUGA.cpp:53]|

05/25/2007 09:39:05.332 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,1,DateIsUndefined: Date [12:00:00 AM 01/00/1900] was found to be an UNDEFINED date [Src/CUGA.cpp:70]|

05/25/2007 09:39:05.332 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [DateIsUndefined]|

Standard contact rule is active.

05/25/2007 09:39:05.332 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,RuleIsActive: Is [Standard] Rule Active = TRUE [Src/PHTransfer.cpp:711]|

05/25/2007 09:39:05.332 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [RuleIsActive]|

05/25/2007 09:39:05.332 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetActiveContactRule: Rule is Active! [Src/PHTransfer.cpp:897]|

05/25/2007 09:39:05.333 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [GetContactRuleProperties]|

All the properties for the contact rule are gotten and stored, one by one, with diags for each, in named properties.

05/25/2007 09:39:05.333 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetContactRuleProperties: ICsNamedProps::SetPropBool(bXferPlayIntro) to value: true returned 0x00000000 S_OK [Src/PHTransfer.cpp:733]|

05/25/2007 09:39:05.333 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetContactRuleProperties: ICsNamedProps::SetPropLong(lXferAction) to value: 0 returned 0x00000000 S_OK [Src/PHTransfer.cpp:737]|

05/25/2007 09:39:05.333 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetContactRuleProperties: ICsNamedProps::SetPropLong(lXferType) to value: 0 returned 0x00000000 S_OK [Src/PHTransfer.cpp:741]|

05/25/2007 09:39:05.333 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetContactRuleProperties: ICsNamedProps::SetPropLong(lXferRings) to value: 4 returned 0x00000000 S_OK [Src/PHTransfer.cpp:745]|

05/25/2007 09:39:05.333 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetContactRuleProperties: ICsNamedProps::SetPropString(strXferExtension) to value:  returned 0x00000000 S_OK [Src/PHTransfer.cpp:749]|

05/25/2007 09:39:05.333 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetContactRuleProperties: ICsNamedProps::SetPropLong(lXferRNAAction) to value: 1 returned 0x00000000 S_OK [Src/PHTransfer.cpp:753]|

A summary diag lists critical transfer options.

05/25/2007 09:39:05.333 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetContactRuleProperties: Transfer options:  Extension=[], action=[0], type=[0], rings=[4], RNA action=[1] [Src/PHTransfer.cpp:756]|

05/25/2007 09:39:05.333 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetContactRuleProperties: ICsNamedProps::SetPropLong(lXferScreeningType) to value: 0 returned 0x00000000 S_OK [Src/PHTransfer.cpp:789]|

05/25/2007 09:39:05.333 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetContactRuleProperties: ICsNamedProps::SetPropLong(lXferHoldingMode) to value: 0 returned 0x00000000 S_OK [Src/PHTransfer.cpp:790]|

05/25/2007 09:39:05.333 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetContactRuleProperties: ICsNamedProps::SetPropBool(bXferIntroduce) to value: false returned 0x00000000 S_OK [Src/PHTransfer.cpp:791]|

05/25/2007 09:39:05.333 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetContactRuleProperties: ICsNamedProps::SetPropBool(bXferConfirm) to value: false returned 0x00000000 S_OK [Src/PHTransfer.cpp:792]|

05/25/2007 09:39:05.333 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetContactRuleProperties: ICsNamedProps::SetPropBool(bXferAnnounce) to value: false returned 0x00000000 S_OK [Src/PHTransfer.cpp:793]|

A summary diag lists critical screening options.

05/25/2007 09:39:05.333 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetContactRuleProperties: Unsupervised transfer: screening=[0], holding mode=[0], introduce=[0], confirm=[0], announce=[0] [Src/PHTransfer.cpp:794]|

05/25/2007 09:39:05.333 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetContactRuleProperties: ICsNamedProps::SetPropVariant(varSwitchID) to value:  returned 0x00000000 S_OK [Src/PHTransfer.cpp:801]|

05/25/2007 09:39:05.333 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [GetContactRuleProperties]|

05/25/2007 09:39:05.333 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [GetActiveContactRule]|

05/25/2007 09:39:05.333 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,LoadInfo_OnEntry: ICsNamedProps::GetPropLong() found property lXferAction = 0.  GetPropLong() returned 0x00000000 S_OK [Src/PHTransfer.cpp:1279]|

05/25/2007 09:39:05.333 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,LoadInfo_OnEntry: ICsNamedProps::GetPropBool() could not find property: bFirstXfr.  GetPropBool() returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:1289]|

05/25/2007 09:39:05.334 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,LoadInfo_OnEntry: ICsNamedProps::SetPropBool(bFirstXfr) to value: false returned 0x00000000 S_OK [Src/PHTransfer.cpp:1292]|

The beginning of a method that determines the redirecting number.

05/25/2007 09:39:05.334 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [GetRedirectingInfo]|

05/25/2007 09:39:05.334 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetRedirectingInfo: System.Conversations.UseLastRedirectingNumber = FALSE [Src/PHTransfer.cpp:126]|

The redirecting number in this case is blank (ext=[]).

05/25/2007 09:39:05.334 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetRedirectingInfo: ICsMiuCall::get_RedirectingID() returned 0x00000000 S_OK, ext=[] [Src/PHTransfer.cpp:148]|

05/25/2007 09:39:05.334 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetRedirectingInfo: ICsMiuCall::get_Reason() returned 0x00000000 S_OK, reason=[1] [Src/PHTransfer.cpp:152]|

05/25/2007 09:39:05.334 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [GetRedirectingInfo]|

05/25/2007 09:39:05.334 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,LoadInfo_OnEntry: ICsNamedProps::GetPropString() found property strDTMFAccessID = .  GetPropString() returned 0x00000000 S_OK [Src/PHTransfer.cpp:1310]|

05/25/2007 09:39:05.334 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [CheckAlternateDtmfIDs]|

05/25/2007 09:39:05.334 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,CheckAlternateDtmfIDs: Looking for a match for DTMF ID [] [Src/PHTransfer.cpp:1166]|

05/25/2007 09:39:05.334 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,CheckAlternateDtmfIDs: Passed strRedirID is empty [Src/PHTransfer.cpp:1180]|

05/25/2007 09:39:05.334 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [CheckAlternateDtmfIDs]|

05/25/2007 09:39:05.334 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,LoadInfo_OnEntry: bFirstXfr=[1], Redir Ext. = [], Access ID = [] bMatch=[0] [Src/PHTransfer.cpp:1325]|

05/25/2007 09:39:05.334 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,LoadInfo_OnEntry: ICsNamedProps::GetPropString() found property strXferExtension = .  GetPropString() returned 0x00000000 S_OK [Src/PHTransfer.cpp:1353]|

05/25/2007 09:39:05.334 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,LoadInfo_OnEntry: ICsEventQueue::PushID(TRUE_EVENT) returned 0x00000000 S_OK [Src/PHTransfer.cpp:1368]|

05/25/2007 09:39:05.334 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [LoadInfo_OnEntry]|

05/25/2007 09:39:05.334 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!LoadInfo] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]|

05/25/2007 09:39:05.334 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Event is [TrueEvent] [Src/CsStateMachine.cpp:165]|

05/25/2007 09:39:05.334 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Next state is [NULL] [Src/CsStateMachine.cpp:187]|

05/25/2007 09:39:05.334 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Exiting state machine. [Src/CsStateMachine.cpp:223]|

05/25/2007 09:39:05.334 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [PHTransfer_RunExit]|

05/25/2007 09:39:05.334 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [RemoveCallFromQueue]|

05/25/2007 09:39:05.335 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,RemoveCallFromQueue: ICsNamedProps::GetPropLong() could not find property: lXferCookie.  GetPropLong() returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:191]|

05/25/2007 09:39:05.335 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [RemoveCallFromQueue]|

05/25/2007 09:39:05.335 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(lXferScreeningType) returned 0x00000000 S_OK [Src/PHTransfer.cpp:224]|

A series of diags showing many properties used by the PHTransfer conversation being removed.  Many conversations clean up after themselves, removing properties that are only relevant to them.

05/25/2007 09:39:05.335 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(vXferScreeningStream) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:225]|

05/25/2007 09:39:05.335 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(bXferScreening) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:226]|

05/25/2007 09:39:05.335 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(lXferType) returned 0x00000000 S_OK [Src/PHTransfer.cpp:227]|

05/25/2007 09:39:05.335 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(lXferAction) returned 0x00000000 S_OK [Src/PHTransfer.cpp:228]|

05/25/2007 09:39:05.335 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(bAskUserUrgent) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:229]|

05/25/2007 09:39:05.335 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(lXferHoldingMode) returned 0x00000000 S_OK [Src/PHTransfer.cpp:230]|

05/25/2007 09:39:05.335 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(bXferAskToHold) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:231]|

05/25/2007 09:39:05.335 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(bXferIntroduce) returned 0x00000000 S_OK [Src/PHTransfer.cpp:232]|

05/25/2007 09:39:05.335 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(bXferConfirm) returned 0x00000000 S_OK [Src/PHTransfer.cpp:233]|

05/25/2007 09:39:05.335 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(bXferAnnounce) returned 0x00000000 S_OK [Src/PHTransfer.cpp:234]|

05/25/2007 09:39:05.335 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(VoiceName) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:235]|

05/25/2007 09:39:05.335 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(lXferPos) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:236]|

05/25/2007 09:39:05.335 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(lXferTimeInQueue) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:237]|

05/25/2007 09:39:05.335 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(lXferRequestsInQueue) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:238]|

05/25/2007 09:39:05.335 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(lXferAvgTimeInQueue) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:239]|

05/25/2007 09:39:05.335 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(bDoAttemptTransfer) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:240]|

05/25/2007 09:39:05.336 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(strAlias) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:241]|

05/25/2007 09:39:05.336 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(bXferGatherPhone) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:242]|

05/25/2007 09:39:05.336 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(bXferGatherAccount) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:243]|

05/25/2007 09:39:05.336 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(CallHandlerAccessID) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:244]|

05/25/2007 09:39:05.336 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(bGotVoiceName) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:245]|

05/25/2007 09:39:05.336 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(bTransferCompleteNeeded) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:246]|

05/25/2007 09:39:05.336 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [PHTransfer_RunExit]|

05/25/2007 09:39:05.336 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,16,PHTransfer : CCsCDEConvBase::Run : Exiting conversation [PHTransfer] [Src/CsCDEConvBase.cpp:390]|

05/25/2007 09:39:05.336 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,16,PHGreeting : CCsCDEConvBase::Run : Entering conversation [PHGreeting] [Src/CsCDEConvBase.cpp:124]|

05/25/2007 09:39:05.336 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [PHGreeting_RunInit]|

05/25/2007 09:39:05.336 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHGreeting_RunInit: ICsNamedProps::GetPropVariant() found property CurEnt = .  GetPropVariant() returned 0x00000000 [Src/PHGreeting.cpp:213]|

Here’s the call handler being processed by the PHGreeting conversation – Opening Greeting, which happens to be a SECONDARY (rather than primary) call handler.

05/25/2007 09:39:05.336 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,PHGreeting_RunInit: Got call handler CurEnt: [{fd848904-5dd6-4823-8e04-1afeb62cc709} Opening Greeting  SECONDARY]  [Src/PHGreeting.cpp:233]|

05/25/2007 09:39:05.336 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [SetLanguageOnContext]|

05/25/2007 09:39:05.336 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,SetLanguageOnContext: Evaluating language settings: bUseCallLanguage=1, lLang=1033 [Src/PHTransfer.cpp:61]|

05/25/2007 09:39:05.336 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,SetLanguageOnContext: Language inheritance requested, leaving context language as [ENU] [Src/PHTransfer.cpp:96]|

05/25/2007 09:39:05.336 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,SetLanguageOnContext: Setting context language to [ENU] [Src/PHTransfer.cpp:102]|

05/25/2007 09:39:05.336 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [SetLanguageOnContext]|

05/25/2007 09:39:05.337 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHGreeting_RunInit: ICsNamedProps::SetPropLong(lAutoAttendantSearchScope) to value: 0 returned 0x00000000 S_OK [Src/PHGreeting.cpp:255]|

05/25/2007 09:39:05.337 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHGreeting_RunInit: ICsNamedProps::SetPropLong(lAfterGreetingDelay) to value: 0 returned 0x00000000 S_OK [Src/PHGreeting.cpp:265]|

05/25/2007 09:39:05.337 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [CheckFullMailBoxFeature]|

05/25/2007 09:39:05.337 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,CheckFullMailBoxFeature: ICsNamedProps::SetPropBool(bCheckSubMboxOutsiderCaller) to value: false returned 0x00000000 S_OK [Src/PHGreeting.cpp:124]|

05/25/2007 09:39:05.337 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,CheckFullMailBoxFeature: ICsNamedProps::SetPropBool(bCheckSubMboxNotifyOutsiderCaller) to value: true returned 0x00000000 S_OK [Src/PHGreeting.cpp:134]|

05/25/2007 09:39:05.337 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [CheckFullMailBoxFeature]|

05/25/2007 09:39:05.337 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHGreeting_RunInit: ICsNamedProps::SetPropBool(bDisableISM) to value: false returned 0x00000000 S_OK [Src/PHGreeting.cpp:275]|

05/25/2007 09:39:05.337 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHGreeting_RunInit: ICsNamedProps::SetPropBool(bCheckRecipientServer) to value: true returned 0x00000000 S_OK [Src/PHGreeting.cpp:283]|

05/25/2007 09:39:05.337 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHGreeting_RunInit: ICsNamedProps::SetPropBool(bSendToOperWhenRec) to value: false returned 0x00000000 S_OK [Src/PHGreeting.cpp:286]|

05/25/2007 09:39:05.337 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHGreeting_RunInit: ICsNamedProps::SetPropBool(bPHGreetingISMBridgeSub) to value: false returned 0x00000000 S_OK [Src/PHGreeting.cpp:289]|

05/25/2007 09:39:05.337 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [PHGreeting_RunInit]|

05/25/2007 09:39:05.337 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [PHGreeting_RunStart]|

05/25/2007 09:39:05.337 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [ClearSubscriberEnvironment]|

05/25/2007 09:39:05.337 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,ClearSubscriberEnvironment: ICsNamedProps::RemoveProp(PromptSpeed) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/SubSignIn.cpp:2555]|

05/25/2007 09:39:05.338 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,ClearSubscriberEnvironment: ICsNamedProps::RemoveProp(PromptVolume) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/SubSignIn.cpp:2556]|

05/25/2007 09:39:05.338 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [ClearSubscriberEnvironment]|

05/25/2007 09:39:05.338 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [PHGreeting_RunStart]|

PHGreeting!PlayGreeting is an important state – every single time we play a call handler’s greeting, this guy does the work.  This is true of system call handlers as well as subscribers’ primary call handlers.  There’s lots of good stuff in here.

05/25/2007 09:39:05.338 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Starting state machine with root state [/opt/cisco/connection/share/tui/PHGreeting.cde!PlayGreeting] [Src/CsStateMachine.cpp:126]|

05/25/2007 09:39:05.338 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/PHGreeting.cde!PlayGreeting] [Src/CsStateMachine.cpp:138]|

05/25/2007 09:39:05.338 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10, : CCustomState::OnEntry : State name=[PlayGreeting] onentry=[PlayGreeting_OnEntry] library=[libConvSub.so] [Src/CustomState.cpp:162]|

05/25/2007 09:39:05.338 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [PlayGreeting_OnEntry]|

05/25/2007 09:39:05.338 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [PlayGreetingInit]|

05/25/2007 09:39:05.338 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [PlayGreetingInit]|

05/25/2007 09:39:05.395 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,PlayGreeting_OnEntry: Call answered if needed. [Src/PHGreeting.cpp:3762]|

05/25/2007 09:39:05.395 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [GetCallHandlerTrafficData]|

05/25/2007 09:39:05.396 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetCallHandlerTrafficData: ICsNamedProps::SetPropString(TrafficDataDTMF) to value:  returned 0x00000000 S_OK [Src/PHGreeting.cpp:494]|

05/25/2007 09:39:05.396 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetCallHandlerTrafficData: ICsNamedProps::SetPropString(TrafficDataText) to value: Opening Greeting returned 0x00000000 S_OK [Src/PHGreeting.cpp:495]|

05/25/2007 09:39:05.396 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetCallHandlerTrafficData: ICsNamedProps::SetPropString(TrafficDataAction) to value: disconnect returned 0x00000000 S_OK [Src/PHGreeting.cpp:496]|

05/25/2007 09:39:05.396 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetCallHandlerTrafficData: ICsNamedProps::SetPropString(TrafficDataActionDTMF) to value:  returned 0x00000000 S_OK [Src/PHGreeting.cpp:497]|

05/25/2007 09:39:05.396 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [GetCallHandlerTrafficData]|

05/25/2007 09:39:05.396 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PlayGreeting_OnEntry: ICsNamedProps::SetPropBool(bCallHandlerData) to value: true returned 0x00000000 S_OK [Src/PHGreeting.cpp:3771]|

05/25/2007 09:39:05.396 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PlayGreeting_OnEntry: ICsNamedProps::GetPropString() could not find property: strOEMOverwriteCallerId.  GetPropString() returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHGreeting.cpp:3776]|

05/25/2007 09:39:05.402 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,PlayGreeting_OnEntry: ICsMiuCall::get_CallerID() returned hr=0x00000000 S_OK, caller ID=[1001]. [Src/PHGreeting.cpp:3781]|

05/25/2007 09:39:05.402 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PlayGreeting_OnEntry: ICsNamedProps::SetPropString(strCallerID) to value: 1001 returned 0x00000000 S_OK [Src/PHGreeting.cpp:3789]|

05/25/2007 09:39:05.402 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,PlayGreeting_OnEntry: ICsMiuCall::get_Origin() returned hr=0x00000000 S_OK, origin=[16]. [Src/PHGreeting.cpp:3795]|

05/25/2007 09:39:05.402 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,PlayGreeting_OnEntry: Checking for subscriber that matches calling number [1001] [Src/PHGreeting.cpp:3804]|

05/25/2007 09:39:05.402 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [GetSubscriberByDtmfIdOrPhoneWithAutoLogon]|

05/25/2007 09:39:05.415 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,16,No Subscriber Records found by Dtmf Access Id 1001 0x80046500 (Src/CsCallSession.cpp 217)|

05/25/2007 09:39:05.415 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetSubscriberByDtmfIdOrPhoneWithAutoLogon: CCsCallSession::GetSubscriberByDtmfId() returned NULL [Src/AttemptSignIn.cpp:59]|

05/25/2007 09:39:05.426 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,16,No Subscriber Records found by Phone Number 1001 0x80046500 (Src/CsCallSession.cpp 266)|

05/25/2007 09:39:05.427 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetSubscriberByDtmfIdOrPhoneWithAutoLogon: CCsCallSession::GetSubscriberByPhoneNumberWithAutoLogon() returned NULL [Src/AttemptSignIn.cpp:65]|

05/25/2007 09:39:05.427 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [GetSubscriberByDtmfIdOrPhoneWithAutoLogon]|

05/25/2007 09:39:05.427 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,PlayGreeting_OnEntry: External call [Src/PHGreeting.cpp:3845]|

05/25/2007 09:39:05.427 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PlayGreeting_OnEntry: ICsNamedProps::GetPropBool() could not find property: bCallBusy.  GetPropBool() returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHGreeting.cpp:3850]|

05/25/2007 09:39:05.427 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PlayGreeting_OnEntry: ICsNamedProps::GetPropBool() found property bFirstXfr = false.  GetPropBool() returned 0x00000000 S_OK [Src/PHGreeting.cpp:3856]|

GetCallHandlerProperties will get all of the important information from the call handler to play the appropriate greeting.  From the following diag lines, we can see, for example, that the one-key dealy is 1500ms, the maximum message length is 300000ms, message editing is set to TRUE, the handler is obeying the “Weekdays” schedule, etc.

05/25/2007 09:39:05.427 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [GetCallHandlerProperties]|

05/25/2007 09:39:05.427 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,1,GetCallHandlerProperties: CH Details: [{fd848904-5dd6-4823-8e04-1afeb62cc709} Opening Greeting  SECONDARY]  [Src/PHGreeting.cpp:2958]|

05/25/2007 09:39:05.431 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetCallHandlerProperties: OBJECT_ID=[{fd848904-5dd6-4823-8e04-1afeb62cc709}] [Src/PHGreeting.cpp:3043]|

05/25/2007 09:39:05.431 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetCallHandlerProperties: LANGUAGE=[1033] [Src/PHGreeting.cpp:3044]|

05/25/2007 09:39:05.431 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetCallHandlerProperties: USE_CALL_LANGUAGE=[TRUE] [Src/PHGreeting.cpp:3045]|

05/25/2007 09:39:05.431 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetCallHandlerProperties: DTMF_ACCESS_ID=[] [Src/PHGreeting.cpp:3046]|

05/25/2007 09:39:05.431 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetCallHandlerProperties: SCHEDULE_OBJECT_NAME=[Weekdays] [Src/PHGreeting.cpp:3047]|

05/25/2007 09:39:05.431 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetCallHandlerProperties: ONEKEY_DELAY=[1500] [Src/PHGreeting.cpp:3048]|

05/25/2007 09:39:05.431 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetCallHandlerProperties: MAX_MSG_LEN=[300000] [Src/PHGreeting.cpp:3049]|

05/25/2007 09:39:05.431 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetCallHandlerProperties: EDIT_MSG=[TRUE] [Src/PHGreeting.cpp:3050]|

05/25/2007 09:39:05.431 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetCallHandlerProperties: SEND_URGENT_MSG=[0] [Src/PHGreeting.cpp:3051]|

05/25/2007 09:39:05.431 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetCallHandlerProperties: AFTER_MESSAGE_ACTION=[2] [Src/PHGreeting.cpp:3052]|

05/25/2007 09:39:05.432 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetCallHandlerProperties: AFTER_MESSAGE_CONVERSATION=[PHGreeting] [Src/PHGreeting.cpp:3053]|

05/25/2007 09:39:05.432 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetCallHandlerProperties: AFTER_MESSAGE_OBJECT_ID=[{f8982c7b-69e6-48d8-a3ce-ae2abdba0dcf}] [Src/PHGreeting.cpp:3057]|

05/25/2007 09:39:05.432 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetCallHandlerProperties: IS_PRIMARY=[FALSE] [Src/PHGreeting.cpp:3058]|

05/25/2007 09:39:05.432 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetCallHandlerProperties: ALIAS=[Opening Greeting] [Src/PHGreeting.cpp:3059]|

05/25/2007 09:39:05.432 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [GetCallHandlerProperties]|

GetMenuEntries diags will show what one-keys are defined, and what they point to.  For example, the “*” (star) key is set to go to the SubSignIn conversation.  This makes sense – pressing “*” at the opening greeting will take you to the subscriber signin conversation.  The 4 key is set to go to the AD (AlphaDirectory) conversation.

05/25/2007 09:39:05.432 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [GetMenuEntries]|

05/25/2007 09:39:05.439 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetMenuEntries: MenuEntry (index=0) key=*: ConvName = SubSignIn !!! [Src/PHGreeting.cpp:3114]|

05/25/2007 09:39:05.439 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetMenuEntries: MenuEntry (index=0) key=*: Target Handler Object Id =  is Not Valid. Conv = SubSignIn !!! [Src/PHGreeting.cpp:3124]|

05/25/2007 09:39:05.439 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetMenuEntries: MenuEntry (index=1) key=#: ConvName = PHTransfer !!! [Src/PHGreeting.cpp:3114]|

05/25/2007 09:39:05.439 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetMenuEntries: MenuEntry (index=1) key=#: Target Handler Object Id = {d0016bbe-79d1-4ff6-a327-cc1a84548a83} - Conv = PHTransfer !!! [Src/PHGreeting.cpp:3129]|

05/25/2007 09:39:05.439 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetMenuEntries: MenuEntry (index=2) key=0: ConvName = PHTransfer !!! [Src/PHGreeting.cpp:3114]|

05/25/2007 09:39:05.439 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetMenuEntries: MenuEntry (index=2) key=0: Target Handler Object Id = {d0016bbe-79d1-4ff6-a327-cc1a84548a83} - Conv = PHTransfer !!! [Src/PHGreeting.cpp:3129]|

The 4 key is set to go to the AD (AlphaDirectory) conversation.  You call also see that the object ID of the target directory handler is {1a75fa5f-7dc1-4227-879b-0f5e5ee7a10d}, in case you need to find it in the database…

05/25/2007 09:39:05.439 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetMenuEntries: MenuEntry (index=6) key=4: ConvName = AD !!! [Src/PHGreeting.cpp:3114]|

05/25/2007 09:39:05.439 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetMenuEntries: MenuEntry (index=6) key=4: Target Handler Object Id = {1a75fa5f-7dc1-4227-879b-0f5e5ee7a10d} - Conv = AD !!! [Src/PHGreeting.cpp:3129]|

05/25/2007 09:39:05.439 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [GetMenuEntries]|

GetActiveMessageRule is going to figure out which greeting to play – Alternate, Standard, Internal, Off-hours, Busy, etc.  If there’s some question about what greeting is playing and why, this’ll tell you how Connection decided what greeting to play.  The greetings are evaluated in order of precedence – the first one found to be active wins.

05/25/2007 09:39:05.439 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [GetActiveMessageRule]|

05/25/2007 09:39:05.446 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [IsRuleActive]|

Error greeting has not expired, but is not active

05/25/2007 09:39:05.446 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,IsRuleActive: Greeting Error has NOT expired. [Src/PHGreeting.cpp:3183]|

05/25/2007 09:39:05.446 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,IsRuleActive: Greeting Error is NOT Active! [Src/PHGreeting.cpp:3267]|

05/25/2007 09:39:05.446 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [IsRuleActive]|

05/25/2007 09:39:05.446 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [GetMessageRuleProperties]|

05/25/2007 09:39:05.446 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [GetMessageRuleProperties]|

05/25/2007 09:39:05.446 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [IsRuleActive]|

Alternate greeting has expired

05/25/2007 09:39:05.446 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,IsRuleActive: Greeting Alternate has expired. [Src/PHGreeting.cpp:3177]|

05/25/2007 09:39:05.447 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [IsRuleActive]|

05/25/2007 09:39:05.447 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [IsRuleActive]|

Busy greeting has expired

05/25/2007 09:39:05.447 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,IsRuleActive: Greeting Busy has expired. [Src/PHGreeting.cpp:3177]|

05/25/2007 09:39:05.447 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [IsRuleActive]|

05/25/2007 09:39:05.447 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [IsRuleActive]|

Internal greeting has expired

05/25/2007 09:39:05.447 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,IsRuleActive: Greeting Internal has expired. [Src/PHGreeting.cpp:3177]|

05/25/2007 09:39:05.447 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [IsRuleActive]|

05/25/2007 09:39:05.447 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [IsRuleActive]|

Holiday greeting has expired

05/25/2007 09:39:05.447 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,IsRuleActive: Greeting Holiday has expired. [Src/PHGreeting.cpp:3177]|

05/25/2007 09:39:05.447 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [IsRuleActive]|

05/25/2007 09:39:05.447 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [IsRuleActive]|

05/25/2007 09:39:05.447 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,IsRuleActive: Greeting Off Hours has NOT expired. [Src/PHGreeting.cpp:3183]|

05/25/2007 09:39:05.447 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,IsRuleActive: ICsNamedProps::GetPropBool() could not find property: bIgnoreOffHoursGreeting.  GetPropBool() returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHGreeting.cpp:3224]|

Alternate greeting has not expired, but is not active

05/25/2007 09:39:05.460 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,IsRuleActive: Greeting Off Hours is NOT Active! [Src/PHGreeting.cpp:3238]|

05/25/2007 09:39:05.460 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [IsRuleActive]|

05/25/2007 09:39:05.460 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [IsRuleActive]|

Standard greeting is always active

05/25/2007 09:39:05.460 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,IsRuleActive: Greeting Standard is always Active! [Src/PHGreeting.cpp:3165]|

05/25/2007 09:39:05.460 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [IsRuleActive]|

05/25/2007 09:39:05.460 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [GetMessageRuleProperties]|

Now we go get the actual greeting associated with the greeting rule.

05/25/2007 09:39:05.460 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [GetRuleGreeting]|

05/25/2007 09:39:05.466 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,1,GetRuleGreeting: Stream LowPart = 244168, Stream HighPart = 0 [Src/PHGreeting.cpp:3331]|

05/25/2007 09:39:05.466 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [GetRuleGreeting]|

05/25/2007 09:39:05.466 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [GetMessageRuleProperties]|

05/25/2007 09:39:05.466 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [GetMessageRuleProperties]|

05/25/2007 09:39:05.466 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [GetRuleGreeting]|

05/25/2007 09:39:05.471 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,1,GetRuleGreeting: Stream LowPart = 244168, Stream HighPart = 0 [Src/PHGreeting.cpp:3331]|

05/25/2007 09:39:05.471 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [GetRuleGreeting]|

05/25/2007 09:39:05.471 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [GetMessageRuleProperties]|

05/25/2007 09:39:05.471 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetActiveMessageRule: [Standard] message rule is active [Src/PHGreeting.cpp:3589]|

We’ve got what we need to play the greeting.  Note that:

Playwhat=1 where

0= play system greeting

1= play personal greeting

2= play no greeting

Action=2 (After greeting action) where

0= ignore

1= hang up

2= go to another handler or conversation

3= error

4= take a message

5= skip greeting

05/25/2007 09:39:05.471 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetActiveMessageRule: Active Greeting :- Type=Standard, PlayWhat=1, Action=2 [Src/PHGreeting.cpp:3613]|

05/25/2007 09:39:05.471 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [GetActiveMessageRule]|

05/25/2007 09:39:05.471 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [SetPlayPromptProps]|

We’re going to be playing the phrase “PersonalGreeting”

05/25/2007 09:39:05.472 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,SetPlayPromptProps: PlayWhat=1, Greeting Action=2 Phrase=PersonalGreeting [Src/PHGreeting.cpp:1649]|

05/25/2007 09:39:05.472 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,SetPlayPromptProps: ICsNamedProps::SetPropLong(lAfterGreetingAction) to value: 2 returned 0x00000000 S_OK [Src/PHGreeting.cpp:1682]|

05/25/2007 09:39:05.472 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,SetPlayPromptProps: PlayWhat: Personal Greeting - Found Recording. [Src/PHGreeting.cpp:1713]|

05/25/2007 09:39:05.472 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,SetPlayPromptProps: ICsNamedProps::SetPropVariant(Greeting) to value:  returned 0x00000000 S_OK [Src/PHGreeting.cpp:1729]|

05/25/2007 09:39:05.472 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [SetPlayPromptProps]|

05/25/2007 09:39:05.472 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,1,PlayGreeting_OnEntry: Ignoring digits [] [Src/PHGreeting.cpp:3957]|

05/25/2007 09:39:05.472 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PlayGreeting_OnEntry: ICsNamedProps::GetPropLong() found property lAfterGreetingDelay = 0.  GetPropLong() returned 0x00000000 S_OK [Src/PHGreeting.cpp:3964]|

05/25/2007 09:39:05.472 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [ProcessUserInput]|

While playing the phrase “PersonalGreeting”, here are some of the flags we’ll be obeying for the play.

05/25/2007 09:39:05.472 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,ProcessUserInput: Processing... bPlayPrompt=[TRUE], iTries=[0], lRepromptDelay=[2000], bIgnoreDigits=[FALSE], lFirstDigitTimeout=[0] [Src/PHGreeting.cpp:2515]|

05/25/2007 09:39:05.472 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,ProcessUserInput: Processing... strDTMFtoIgnore=[], strPhraseID=[PersonalGreeting] [Src/PHGreeting.cpp:2516]|

05/25/2007 09:39:05.472 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,ProcessUserInput: Call Handler's alternate greeting is not active! [Src/PHGreeting.cpp:2571]|

05/25/2007 09:39:05.472 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [DisplayGreetingStatus]|

05/25/2007 09:39:05.472 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [UpdateMonitorWithGreetingInfo]|

05/25/2007 09:39:05.472 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,UpdateMonitorWithGreetingInfo: Playing greeting for Call Handler:  Opening Greeting [Src/PHGreeting.cpp:106]|

05/25/2007 09:39:05.472 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [UpdateMonitorWithGreetingInfo]|

05/25/2007 09:39:05.472 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [DisplayGreetingStatus]|

05/25/2007 09:39:05.472 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,ProcessUserInput: ICsNamedProps::SetPropLong(lRepromptGreeting) to value: 0 returned 0x00000000 S_OK [Src/PHGreeting.cpp:2601]|

Now we actual make and play the phrase, using the personal greeting of the opening greeting call handler.

05/25/2007 09:39:05.472 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [PlayPrompt]|

05/25/2007 09:39:05.472 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,PhraseServer,3,(SingleUse.cpp) Script: PHGreeting_ENU.ps (Make) -- PersonalGreeting|

05/25/2007 09:39:05.473 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,PhraseServer,3,(SingleUse.cpp) Script: PHGreeting_ENU.ps (AddObject) -- Greeting|

05/25/2007 09:39:05.473 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,1,PlayPrompt: Phrase [PersonalGreeting] made for greeting for call handler id [] with alias [Opening Greeting]. [Src/PHGreeting.cpp:720]|

Here’s the actual .wav file being played: /var/opt/cisco/connection/lib/streams/68182e27-2d69-43bb-b93f-3843dca83023.wav

05/25/2007 09:39:05.586 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,PhraseServer,-1,CCsPhrase::ConvertIBaseFileName() :         $Stream - /var/opt/cisco/connection/lib/streams/68182e27-2d69-43bb-b93f-3843dca83023.wav [Src/CsPhrase.cpp:1146]|

05/25/2007 09:39:06.345 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,PhraseServer,6,CCsPhrase::Play() :     End Phrase [Src/CsPhrase.cpp:509]|

05/25/2007 09:39:06.345 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [PlayPrompt]|

We’ve played the greeting, and now it’s time to see if the caller pressed any touchtones while the greeting was playing.

05/25/2007 09:39:06.345 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [GatherDigits]|

05/25/2007 09:39:06.345 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,1,GatherDigits: put_GatherFirstDigitTimeout(0) returned 0x00000000 S_OK [Src/PHGreeting.cpp:2256]|

We gather the very first digit (digits=[1]), and “1”

05/25/2007 09:39:06.346 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,1,GatherDigits: GatherDigits() returned 0x00000000 S_OK, digits=[1], num=[1] [Src/PHGreeting.cpp:2269]|

05/25/2007 09:39:06.346 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GatherDigits: DTMF received [1] [Src/PHGreeting.cpp:2277]|

05/25/2007 09:39:06.346 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GatherDigits: Matched one-key [1] [Src/PHGreeting.cpp:2304]|

05/25/2007 09:39:06.346 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,1,GatherDigits: put_IgnoreDigits() returned 0x00000000 S_OK [Src/PHGreeting.cpp:2370]|

We’ll wait for more digits to come in, using interdigit timeouts to limit how long we wait.

05/25/2007 09:39:06.346 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GatherDigits: Gathering additional digits... [Src/PHGreeting.cpp:2372]|

We got three more (num=[3]) digits, all “0” (digits=[000])

05/25/2007 09:39:08.475 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,1,GatherDigits: GatherDigits() returned 0x00045b35 S_MIU_TERM_TIMEOUT, digits=[000], num=[3] [Src/PHGreeting.cpp:2382]|

We put them all together to figure out what the caller entered - 1000

05/25/2007 09:39:08.475 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GatherDigits: Adding digits - digits gathered so far are [1000] [Src/PHGreeting.cpp:2408]|

05/25/2007 09:39:08.475 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [GatherDigits]|

So far so good – we gathered “1000”

05/25/2007 09:39:08.475 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,ProcessUserInput: GatherDigits() succeeded. Digits=[1000], Menu Index =[-1] [Src/PHGreeting.cpp:2650]|

05/25/2007 09:39:08.475 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,ProcessUserInput: Processing return from GatherDigits() hr=0x00041903 S_GOT_DTMF [Src/PHGreeting.cpp:2668]|

05/25/2007 09:39:08.476 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,ProcessUserInput: ICsNamedProps::SetPropString(TrafficDataAction) to value: 1000 returned 0x00043210 S_NP_PROP_REPLACED [Src/PHGreeting.cpp:2788]|

Now we go look to see what “1000” means…

05/25/2007 09:39:08.476 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [VerifyDTMF]|

Apparently, it’s a call handler…

05/25/2007 09:39:08.485 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,VerifyDTMF: Found call handler for dtmf id [1000] [Src/PHGreeting.cpp:1822]|

…with object id= {0bc2071a-4a4b-42d1-835f-cb9a985a1d11}

05/25/2007 09:39:08.485 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,VerifyDTMF: Object ID of handler is [{0bc2071a-4a4b-42d1-835f-cb9a985a1d11}] [Src/PHGreeting.cpp:1829]|

05/25/2007 09:39:08.485 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,VerifyDTMF: ICsNamedProps::SetPropString(TrafficDataAction) to value: id returned 0x00043210 S_NP_PROP_REPLACED [Src/PHGreeting.cpp:1880]|

Any time the “CurEnt” property is being set, we’re heading for another object (handler) – the lines following this show the PHGreeting conversation for the Opening Greeting call handler winding down.

05/25/2007 09:39:08.489 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,VerifyDTMF: ICsNamedProps::SetPropVariant(CurEnt) to value:  returned 0x00043210 S_NP_PROP_REPLACED [Src/PHGreeting.cpp:1890]|

05/25/2007 09:39:08.489 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,VerifyDTMF: ICsNamedProps::GetPropBool() could not find property: bTransferOverride.  GetPropBool() returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHGreeting.cpp:1896]|

05/25/2007 09:39:08.496 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,VerifyDTMF: Send call to PHTransfer [Src/PHGreeting.cpp:1933]|

05/25/2007 09:39:08.500 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [VerifyDTMF]|

05/25/2007 09:39:08.500 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [ProcessUserInput]|

05/25/2007 09:39:08.500 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PlayGreeting_OnEntry: ICsNamedProps::RemoveProp(Greeting) returned 0x00000000 S_OK [Src/PHGreeting.cpp:3979]|

05/25/2007 09:39:08.500 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PlayGreeting_OnEntry: ICsNamedProps::RemoveProp(VoiceName) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHGreeting.cpp:3980]|

05/25/2007 09:39:08.500 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PlayGreeting_OnEntry: ICsNamedProps::RemoveProp(CallHandlerAccessID) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHGreeting.cpp:3981]|

05/25/2007 09:39:08.500 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PlayGreeting_OnEntry: ICsNamedProps::RemoveProp(fVoiceNameAvailable) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHGreeting.cpp:3982]|

05/25/2007 09:39:08.500 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PlayGreeting_OnEntry: ICsNamedProps::RemoveProp(bTransferOverride) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHGreeting.cpp:3983]|

05/25/2007 09:39:08.500 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PlayGreeting_OnEntry: ICsNamedProps::GetPropBool() could not find property: bUseErrorMsgRule.  GetPropBool() returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHGreeting.cpp:3986]|

05/25/2007 09:39:08.500 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,PlayGreeting_OnEntry: Either bUseErrorMsgRule is false or S_CALL_COMPLETE was returned [Src/PHGreeting.cpp:4003]|

05/25/2007 09:39:08.500 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [PlayGreeting_OnEntry]|

05/25/2007 09:39:08.500 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/PHGreeting.cde!PlayGreeting] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]|

05/25/2007 09:39:08.500 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Event is [NULL] [Src/CsStateMachine.cpp:165]|

Next state is NULL – again, this means the conversation is ending. There will follow a lot of conversation cleanup diags…

05/25/2007 09:39:08.500 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Next state is [NULL] [Src/CsStateMachine.cpp:187]|

05/25/2007 09:39:08.500 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10, : CCustomState::OnExit : State name=[PlayGreeting] onexit=[PlayGreeting_OnExit] library=[libConvSub.so] [Src/CustomState.cpp:263]|

05/25/2007 09:39:08.500 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [PlayGreeting_OnExit]|

05/25/2007 09:39:08.501 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PlayGreeting_OnExit: ICsNamedProps::RemoveProp(bUseErrorMsgRule) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHGreeting.cpp:4030]|

05/25/2007 09:39:08.501 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PlayGreeting_OnExit: ICsNamedProps::GetPropBool() found property bCallHandlerData = true.  GetPropBool() returned 0x00000000 S_OK [Src/PHGreeting.cpp:4036]|

05/25/2007 09:39:08.501 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [PutCallHandlerTrafficData]|

05/25/2007 09:39:08.501 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PutCallHandlerTrafficData: ICsNamedProps::GetPropString() found property TrafficDataDTMF = .  GetPropString() returned 0x00000000 S_OK [Src/PHGreeting.cpp:540]|

05/25/2007 09:39:08.501 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PutCallHandlerTrafficData: ICsNamedProps::GetPropString() found property TrafficDataText = Opening Greeting.  GetPropString() returned 0x00000000 S_OK [Src/PHGreeting.cpp:543]|

05/25/2007 09:39:08.501 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PutCallHandlerTrafficData: ICsNamedProps::GetPropString() found property TrafficDataAction = id.  GetPropString() returned 0x00000000 S_OK [Src/PHGreeting.cpp:546]|

05/25/2007 09:39:08.501 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PutCallHandlerTrafficData: ICsNamedProps::GetPropString() found property TrafficDataActionDTMF = .  GetPropString() returned 0x00000000 S_OK [Src/PHGreeting.cpp:549]|

05/25/2007 09:39:08.501 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [PutCallHandlerTrafficData]|

05/25/2007 09:39:08.501 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PlayGreeting_OnExit: ICsNamedProps::RemoveProp(TrafficDataDTMF) returned 0x00000000 S_OK [Src/PHGreeting.cpp:4042]|

05/25/2007 09:39:08.501 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PlayGreeting_OnExit: ICsNamedProps::RemoveProp(TrafficDataText) returned 0x00000000 S_OK [Src/PHGreeting.cpp:4043]|

05/25/2007 09:39:08.501 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PlayGreeting_OnExit: ICsNamedProps::RemoveProp(TrafficDataAction) returned 0x00000000 S_OK [Src/PHGreeting.cpp:4044]|

05/25/2007 09:39:08.501 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PlayGreeting_OnExit: ICsNamedProps::RemoveProp(TrafficDataActionDTMF) returned 0x00000000 S_OK [Src/PHGreeting.cpp:4045]|

05/25/2007 09:39:08.502 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PlayGreeting_OnExit: ICsNamedProps::RemoveProp(bCallHandlerData) returned 0x00000000 S_OK [Src/PHGreeting.cpp:4046]|

05/25/2007 09:39:08.502 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [PlayGreeting_OnExit]|

05/25/2007 09:39:08.502 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Exiting state machine. [Src/CsStateMachine.cpp:223]|

05/25/2007 09:39:08.502 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [PHGreeting_RunExit]|

05/25/2007 09:39:08.502 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHGreeting_RunExit: ICsNamedProps::RemoveProp(bCallBusy) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHGreeting.cpp:156]|

05/25/2007 09:39:08.502 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHGreeting_RunExit: ICsNamedProps::RemoveProp(lAfterGreetingAction) returned 0x00000000 S_OK [Src/PHGreeting.cpp:157]|

05/25/2007 09:39:08.502 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHGreeting_RunExit: ICsNamedProps::RemoveProp(bIgnoreBusyGreeting) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHGreeting.cpp:158]|

05/25/2007 09:39:08.502 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHGreeting_RunExit: ICsNamedProps::RemoveProp(bIgnoreInternalGreeting) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHGreeting.cpp:159]|

05/25/2007 09:39:08.502 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHGreeting_RunExit: ICsNamedProps::RemoveProp(bIgnoreOffHoursGreeting) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHGreeting.cpp:160]|

05/25/2007 09:39:08.502 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHGreeting_RunExit: ICsNamedProps::RemoveProp(bCheckSubMboxOutsiderCaller) returned 0x00000000 S_OK [Src/PHGreeting.cpp:161]|

05/25/2007 09:39:08.502 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHGreeting_RunExit: ICsNamedProps::RemoveProp(bCheckSubMboxNotifyOutsiderCaller) returned 0x00000000 S_OK [Src/PHGreeting.cpp:162]|

05/25/2007 09:39:08.502 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHGreeting_RunExit: ICsNamedProps::RemoveProp(bSendToOperWhenRec) returned 0x00000000 S_OK [Src/PHGreeting.cpp:163]|

05/25/2007 09:39:08.502 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHGreeting_RunExit: ICsNamedProps::RemoveProp(strDialingDomainSubEMAIL) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHGreeting.cpp:164]|

05/25/2007 09:39:08.502 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHGreeting_RunExit: ICsNamedProps::RemoveProp(bCheckRecipientServer) returned 0x00000000 S_OK [Src/PHGreeting.cpp:165]|

05/25/2007 09:39:08.502 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [PHGreeting_RunExit]|

PHGreeting is over…

05/25/2007 09:39:08.502 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,16,PHGreeting : CCsCDEConvBase::Run : Exiting conversation [PHGreeting] [Src/CsCDEConvBase.cpp:390]|

PHTransfer is firing up…

05/25/2007 09:39:08.502 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,16,PHTransfer : CCsCDEConvBase::Run : Entering conversation [PHTransfer] [Src/CsCDEConvBase.cpp:124]|

05/25/2007 09:39:08.503 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [PHTransfer_RunInit]|

05/25/2007 09:39:08.503 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHTransfer_RunInit: ICsNamedProps::GetPropBool() could not find property: bUseDialingDomainXfer.  GetPropBool() returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:287]|

05/25/2007 09:39:08.503 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,PHTransfer_RunInit: ICsNamedProps::GetPropVariant() found property CurEnt = .  GetPropVariant() returned 0x00000000 [Src/PHTransfer.cpp:302]|

Here’s the next call handler we’re dealing with “Marketing Transfer”, at ID 1000, another SECONDARY call handler. What follows are similar diags to what we saw for the “Opening Greering” handler.

05/25/2007 09:39:08.503 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,PHTransfer_RunInit: Got call handler [{0bc2071a-4a4b-42d1-835f-cb9a985a1d11} Marketing Transfer 1000 SECONDARY]  [Src/PHTransfer.cpp:322]|

05/25/2007 09:39:08.503 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [SetLanguageOnContext]|

05/25/2007 09:39:08.503 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,SetLanguageOnContext: Evaluating language settings: bUseCallLanguage=1, lLang=1033 [Src/PHTransfer.cpp:61]|

05/25/2007 09:39:08.503 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,SetLanguageOnContext: Language inheritance requested, leaving context language as [ENU] [Src/PHTransfer.cpp:96]|

05/25/2007 09:39:08.503 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,SetLanguageOnContext: Setting context language to [ENU] [Src/PHTransfer.cpp:102]|

05/25/2007 09:39:08.503 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [SetLanguageOnContext]|

05/25/2007 09:39:08.503 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [PHTransfer_RunInit]|

05/25/2007 09:39:08.503 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [PHTransfer_RunStart]|

05/25/2007 09:39:08.503 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [ClearSubscriberEnvironment]|

05/25/2007 09:39:08.503 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,ClearSubscriberEnvironment: ICsNamedProps::RemoveProp(PromptSpeed) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/SubSignIn.cpp:2555]|

05/25/2007 09:39:08.503 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,ClearSubscriberEnvironment: ICsNamedProps::RemoveProp(PromptVolume) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/SubSignIn.cpp:2556]|

05/25/2007 09:39:08.503 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [ClearSubscriberEnvironment]|

05/25/2007 09:39:08.503 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [PHTransfer_RunStart]|

05/25/2007 09:39:08.503 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Starting state machine with root state [/opt/cisco/connection/share/tui/PHTransfer.cde!CheckRoutingRuleXfer] [Src/CsStateMachine.cpp:126]|

05/25/2007 09:39:08.504 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!CheckRoutingRuleXfer] [Src/CsStateMachine.cpp:138]|

05/25/2007 09:39:08.504 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!CheckRoutingRuleXfer] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]|

05/25/2007 09:39:08.504 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Event is [NULL] [Src/CsStateMachine.cpp:165]|

05/25/2007 09:39:08.504 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/PHTransfer.cde!LoadInfo] [Src/CsStateMachine.cpp:187]|

05/25/2007 09:39:08.504 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!LoadInfo] [Src/CsStateMachine.cpp:138]|

05/25/2007 09:39:08.504 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10, : CCustomState::OnEntry : State name=[LoadInfo] onentry=[LoadInfo_OnEntry] library=[libConvSub.so] [Src/CustomState.cpp:162]|

05/25/2007 09:39:08.504 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [LoadInfo_OnEntry]|

05/25/2007 09:39:08.504 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,LoadInfo_OnEntry: ICsNamedProps::GetPropBool() could not find property: bUseDialingDomainXfer.  GetPropBool() returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:1243]|

05/25/2007 09:39:08.504 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [GetActiveContactRule]|

05/25/2007 09:39:08.504 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetActiveContactRule: ICsNamedProps::SetPropString(strDTMFAccessID) to value: 1000 returned 0x00043210 S_NP_PROP_REPLACED [Src/PHTransfer.cpp:824]|

05/25/2007 09:39:08.529 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetActiveContactRule: Schedule mode is [0] [Src/PHTransfer.cpp:841]|

05/25/2007 09:39:08.529 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetActiveContactRule: ICsNamedProps::SetPropVariant(varObjectID) to value:  returned 0x00043210 S_NP_PROP_REPLACED [Src/PHTransfer.cpp:851]|

05/25/2007 09:39:08.537 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [RuleIsActive]|

05/25/2007 09:39:08.537 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [DateIsUndefined]|

05/25/2007 09:39:08.537 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,1,DateIsUndefined: Checking date [12:00:00 AM 01/01/1972] against undefined values [Src/CUGA.cpp:53]|

05/25/2007 09:39:08.537 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,1,DateIsUndefined: Date [12:00:00 AM 01/01/1972] was found to be a valid, defined date [Src/CUGA.cpp:70]|

05/25/2007 09:39:08.537 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [DateIsUndefined]|

05/25/2007 09:39:08.537 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,RuleIsActive: Is [Alternate] Rule Active = FALSE [Src/PHTransfer.cpp:711]|

05/25/2007 09:39:08.537 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [RuleIsActive]|

05/25/2007 09:39:08.537 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetActiveContactRule: Alternate Transfer Option is not Active! [Src/PHTransfer.cpp:862]|

05/25/2007 09:39:08.537 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetActiveContactRule: Contact rule being used is [Standard] [Src/PHTransfer.cpp:881]|

05/25/2007 09:39:08.537 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [RuleIsActive]|

05/25/2007 09:39:08.537 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [DateIsUndefined]|

05/25/2007 09:39:08.537 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,1,DateIsUndefined: Checking date [12:00:00 AM 01/00/1900] against undefined values [Src/CUGA.cpp:53]|

05/25/2007 09:39:08.537 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,1,DateIsUndefined: Date [12:00:00 AM 01/00/1900] was found to be an UNDEFINED date [Src/CUGA.cpp:70]|

05/25/2007 09:39:08.537 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [DateIsUndefined]|

The standard transfer rule is active

05/25/2007 09:39:08.537 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,RuleIsActive: Is [Standard] Rule Active = TRUE [Src/PHTransfer.cpp:711]|

05/25/2007 09:39:08.537 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [RuleIsActive]|

05/25/2007 09:39:08.537 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetActiveContactRule: Rule is Active! [Src/PHTransfer.cpp:897]|

05/25/2007 09:39:08.537 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [GetContactRuleProperties]|

05/25/2007 09:39:08.537 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetContactRuleProperties: ICsNamedProps::SetPropBool(bXferPlayIntro) to value: true returned 0x00043210 S_NP_PROP_REPLACED [Src/PHTransfer.cpp:733]|

05/25/2007 09:39:08.537 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetContactRuleProperties: ICsNamedProps::SetPropLong(lXferAction) to value: 1 returned 0x00000000 S_OK [Src/PHTransfer.cpp:737]|

05/25/2007 09:39:08.538 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetContactRuleProperties: ICsNamedProps::SetPropLong(lXferType) to value: 0 returned 0x00000000 S_OK [Src/PHTransfer.cpp:741]|

05/25/2007 09:39:08.538 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetContactRuleProperties: ICsNamedProps::SetPropLong(lXferRings) to value: 4 returned 0x00043210 S_NP_PROP_REPLACED [Src/PHTransfer.cpp:745]|

05/25/2007 09:39:08.538 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetContactRuleProperties: ICsNamedProps::SetPropString(strXferExtension) to value: 1000 returned 0x00043210 S_NP_PROP_REPLACED [Src/PHTransfer.cpp:749]|

05/25/2007 09:39:08.538 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetContactRuleProperties: ICsNamedProps::SetPropLong(lXferRNAAction) to value: 1 returned 0x00043210 S_NP_PROP_REPLACED [Src/PHTransfer.cpp:753]|

Transfer options indicate a transfer.

05/25/2007 09:39:08.538 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetContactRuleProperties: Transfer options:  Extension=[1000], action=[1], type=[0], rings=[4], RNA action=[1] [Src/PHTransfer.cpp:756]|

05/25/2007 09:39:08.538 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetContactRuleProperties: ICsNamedProps::SetPropLong(lXferScreeningType) to value: 0 returned 0x00000000 S_OK [Src/PHTransfer.cpp:789]|

05/25/2007 09:39:08.538 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetContactRuleProperties: ICsNamedProps::SetPropLong(lXferHoldingMode) to value: 0 returned 0x00000000 S_OK [Src/PHTransfer.cpp:790]|

05/25/2007 09:39:08.538 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetContactRuleProperties: ICsNamedProps::SetPropBool(bXferIntroduce) to value: false returned 0x00000000 S_OK [Src/PHTransfer.cpp:791]|

05/25/2007 09:39:08.538 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetContactRuleProperties: ICsNamedProps::SetPropBool(bXferConfirm) to value: false returned 0x00000000 S_OK [Src/PHTransfer.cpp:792]|

05/25/2007 09:39:08.538 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetContactRuleProperties: ICsNamedProps::SetPropBool(bXferAnnounce) to value: false returned 0x00000000 S_OK [Src/PHTransfer.cpp:793]|

Details about the upcoming transfer

05/25/2007 09:39:08.538 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetContactRuleProperties: Unsupervised transfer: screening=[0], holding mode=[0], introduce=[0], confirm=[0], announce=[0] [Src/PHTransfer.cpp:794]|

05/25/2007 09:39:08.538 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetContactRuleProperties: ICsNamedProps::SetPropVariant(varSwitchID) to value:  returned 0x00043210 S_NP_PROP_REPLACED [Src/PHTransfer.cpp:801]|

05/25/2007 09:39:08.538 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [GetContactRuleProperties]|

05/25/2007 09:39:08.538 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [GetActiveContactRule]|

05/25/2007 09:39:08.538 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,LoadInfo_OnEntry: ICsNamedProps::GetPropLong() found property lXferAction = 1.  GetPropLong() returned 0x00000000 S_OK [Src/PHTransfer.cpp:1279]|

05/25/2007 09:39:08.538 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,LoadInfo_OnEntry: ICsNamedProps::GetPropBool() found property bFirstXfr = false.  GetPropBool() returned 0x00000000 S_OK [Src/PHTransfer.cpp:1289]|

05/25/2007 09:39:08.538 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,LoadInfo_OnEntry: ICsNamedProps::SetPropBool(bFirstXfr) to value: false returned 0x00043210 S_NP_PROP_REPLACED [Src/PHTransfer.cpp:1292]|

05/25/2007 09:39:08.538 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [GetRedirectingInfo]|

05/25/2007 09:39:08.538 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetRedirectingInfo: System.Conversations.UseLastRedirectingNumber = FALSE [Src/PHTransfer.cpp:126]|

05/25/2007 09:39:08.539 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetRedirectingInfo: ICsMiuCall::get_RedirectingID() returned 0x00000000 S_OK, ext=[] [Src/PHTransfer.cpp:148]|

05/25/2007 09:39:08.539 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,GetRedirectingInfo: ICsMiuCall::get_Reason() returned 0x00000000 S_OK, reason=[1] [Src/PHTransfer.cpp:152]|

05/25/2007 09:39:08.539 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [GetRedirectingInfo]|

05/25/2007 09:39:08.539 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,LoadInfo_OnEntry: ICsNamedProps::GetPropString() found property strDTMFAccessID = 1000.  GetPropString() returned 0x00000000 S_OK [Src/PHTransfer.cpp:1310]|

05/25/2007 09:39:08.539 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [CheckAlternateDtmfIDs]|

05/25/2007 09:39:08.539 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,CheckAlternateDtmfIDs: Looking for a match for DTMF ID [] [Src/PHTransfer.cpp:1166]|

05/25/2007 09:39:08.539 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,CheckAlternateDtmfIDs: Passed strRedirID is empty [Src/PHTransfer.cpp:1180]|

05/25/2007 09:39:08.539 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [CheckAlternateDtmfIDs]|

05/25/2007 09:39:08.539 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,LoadInfo_OnEntry: bFirstXfr=[0], Redir Ext. = [], Access ID = [1000] bMatch=[0] [Src/PHTransfer.cpp:1325]|

05/25/2007 09:39:08.539 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,LoadInfo_OnEntry: ICsNamedProps::GetPropString() found property strXferExtension = 1000.  GetPropString() returned 0x00000000 S_OK [Src/PHTransfer.cpp:1353]|

05/25/2007 09:39:08.545 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,4,LoadInfo_OnEntry: Answer Phone if needed [Src/PHTransfer.cpp:1401]|

05/25/2007 09:39:08.545 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [GetTransferEnv]|

05/25/2007 09:39:08.545 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetTransferEnv: ICsNamedProps::SetPropLong(lXferAttempts) to value: 5 returned 0x00000000 S_OK [Src/PHTransfer.cpp:951]|

05/25/2007 09:39:08.545 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetTransferEnv: ICsNamedProps::SetPropLong(lXferAttemptsWaitTime) to value: 5 returned 0x00000000 S_OK [Src/PHTransfer.cpp:952]|

05/25/2007 09:39:08.546 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetTransferEnv: ICsNamedProps::SetPropBool(bXferNewCall) to value: true returned 0x00000000 S_OK [Src/PHTransfer.cpp:953]|

05/25/2007 09:39:08.546 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [GetTransferEnv]|

05/25/2007 09:39:08.546 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,LoadInfo_OnEntry: ICsNamedProps::GetPropLong() found property lXferType = 0.  GetPropLong() returned 0x00000000 S_OK [Src/PHTransfer.cpp:1418]|

05/25/2007 09:39:08.546 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,LoadInfo_OnEntry: ICsNamedProps::GetPropBool() found property bXferIntroduce = false.  GetPropBool() returned 0x00000000 S_OK [Src/PHTransfer.cpp:1429]|

05/25/2007 09:39:08.546 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,LoadInfo_OnEntry: ICsNamedProps::GetPropLong() found property lXferScreeningType = 0.  GetPropLong() returned 0x00000000 S_OK [Src/PHTransfer.cpp:1432]|

05/25/2007 09:39:08.546 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,LoadInfo_OnEntry: ICsNamedProps::GetPropLong() found property lXferHoldingMode = 0.  GetPropLong() returned 0x00000000 S_OK [Src/PHTransfer.cpp:1443]|

05/25/2007 09:39:08.546 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,5,LoadInfo_OnEntry: ICsEventQueue::PushID(FALSE_EVENT) returned 0x00000000 S_OK [Src/PHTransfer.cpp:1468]|

05/25/2007 09:39:08.546 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [LoadInfo_OnEntry]|

05/25/2007 09:39:08.546 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!LoadInfo] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]|

05/25/2007 09:39:08.546 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Event is [FalseEvent] [Src/CsStateMachine.cpp:165]|

Check to see if we need to play the transfer introduction

05/25/2007 09:39:08.546 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/PHTransfer.cde!CheckPlayTransferIntro] [Src/CsStateMachine.cpp:187]|

05/25/2007 09:39:08.546 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!CheckPlayTransferIntro] [Src/CsStateMachine.cpp:138]|

05/25/2007 09:39:08.546 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!CheckPlayTransferIntro] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]|

We DO we need to play the transfer introduction

05/25/2007 09:39:08.546 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Event is [TrueEvent] [Src/CsStateMachine.cpp:165]|

Off to try to play the introduction

05/25/2007 09:39:08.546 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/PHTransfer.cde!PlayTransferIntro] [Src/CsStateMachine.cpp:187]|

05/25/2007 09:39:08.546 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!PlayTransferIntro] [Src/CsStateMachine.cpp:138]|

05/25/2007 09:39:08.547 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,16,Current subscriber not set in the session 0x0 (Src/CsCallSession.cpp 70)|

05/25/2007 09:39:08.547 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,16,Current subscriber not set in the session 0x0 (Src/CsCallSession.cpp 70)|

05/25/2007 09:39:08.547 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,16,Current subscriber not set in the session 0x0 (Src/CsCallSession.cpp 70)|

05/25/2007 09:39:08.547 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,16, : CCsSPlayPhrase::OnEntry : Couldn't find PhraseStartPosition in named props, assuming 0 [Src/CsSPlayPhrase.cpp:243]|

Making the phrase “PlayIntro” from the PHGreeting_ENU.ps phrase server file.

05/25/2007 09:39:08.547 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,PhraseServer,3,(SingleUse.cpp) Script: PHGreeting_ENU.ps (Make) -- PlayIntro|

Adding a prompt…

05/25/2007 09:39:08.547 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,PhraseServer,3,(SingleUse.cpp) Script: PHGreeting_ENU.ps (AddPrompt) -- PleaseWaitForTransfer|

05/25/2007 09:39:08.575 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,PhraseServer,6,CCsPhrase::ConvertStrFileName() :         Prompt Name - /opt/cisco/connection/share/prompts/ENU/PCM/PHGreet/AvPHGreetENU005.wav [Src/CsPhrase.cpp:1222]|

05/25/2007 09:39:10.636 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,PhraseServer,6,CCsPhrase::Play() :     End Phrase [Src/CsPhrase.cpp:509]|

05/25/2007 09:39:10.636 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,16,Current subscriber not set in the session 0x0 (Src/CsCallSession.cpp 70)|

05/25/2007 09:39:10.636 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,16,Current subscriber not set in the session 0x0 (Src/CsCallSession.cpp 70)|

05/25/2007 09:39:10.636 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!PlayTransferIntro] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]|

05/25/2007 09:39:10.636 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Event is [NULL] [Src/CsStateMachine.cpp:165]|

05/25/2007 09:39:10.636 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/PHTransfer.cde!XferCall] [Src/CsStateMachine.cpp:187]|

XferCall will actually perform the call transfer

05/25/2007 09:39:10.636 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!XferCall] [Src/CsStateMachine.cpp:138]|

05/25/2007 09:39:10.636 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,CDE,10, : CCustomState::OnEntry : State name=[XferCall] onentry=[XferCall_OnEntry] library=[libConvSub.so] [Src/CustomState.cpp:162]|

05/25/2007 09:39:10.636 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [XferCall_OnEntry]|

XferCall gathers the properties necessary to complete the transfer according to the call handler’s settings

05/25/2007 09:39:10.636 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,XferCall_OnEntry: ICsNamedProps::GetPropLong() found property lXferType = 0.  GetPropLong() returned 0x00000000 S_OK [Src/PHTransfer.cpp:2145]|

05/25/2007 09:39:10.636 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,XferCall_OnEntry: ICsNamedProps::GetPropBool() could not find property: bUseDialingDomainXfer.  GetPropBool() returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:2148]|

05/25/2007 09:39:10.636 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,XferCall_OnEntry: ICsNamedProps::GetPropString() found property strXferExtension = 1000.  GetPropString() returned 0x00000000 S_OK [Src/PHTransfer.cpp:2152]|

05/25/2007 09:39:10.636 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,XferCall_OnEntry: ICsNamedProps::GetPropLong() found property lXferRings = 4.  GetPropLong() returned 0x00000000 S_OK [Src/PHTransfer.cpp:2156]|

05/25/2007 09:39:10.636 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,XferCall_OnEntry: ICsNamedProps::GetPropVariant() found property varObjectID = .  GetPropVariant() returned 0x00000000 [Src/PHTransfer.cpp:2161]|

05/25/2007 09:39:10.636 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,XferCall_OnEntry: ICsNamedProps::GetPropVariant() found property varSwitchID = .  GetPropVariant() returned 0x00000000 [Src/PHTransfer.cpp:2167]|

GetTransferBillingData gathers information necessary for the Transfer Call Billing report

05/25/2007 09:39:10.636 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [GetTransferBillingData]|

05/25/2007 09:39:10.636 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetTransferBillingData: ICsNamedProps::SetPropString(TransferBillingDTMF) to value: 1000 returned 0x00000000 S_OK [Src/PHTransfer.cpp:2100]|

05/25/2007 09:39:10.637 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetTransferBillingData: ICsNamedProps::SetPropString(TransferBillingBillId) to value:  returned 0x00000000 S_OK [Src/PHTransfer.cpp:2101]|

05/25/2007 09:39:10.637 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetTransferBillingData: ICsNamedProps::SetPropString(TransferBillingObjectType) to value: 3 returned 0x00000000 S_OK [Src/PHTransfer.cpp:2102]|

05/25/2007 09:39:10.637 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetTransferBillingData: ICsNamedProps::SetPropString(TransferBillingAlias) to value: Marketing Transfer returned 0x00000000 S_OK [Src/PHTransfer.cpp:2103]|

05/25/2007 09:39:10.637 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetTransferBillingData: ICsNamedProps::SetPropString(TransferBillingExtension) to value:  returned 0x00000000 S_OK [Src/PHTransfer.cpp:2104]|

05/25/2007 09:39:10.637 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,GetTransferBillingData: ICsNamedProps::SetPropString(TransferBillingCallHandlerId) to value: {0bc2071a-4a4b-42d1-835f-cb9a985a1d11} returned 0x00000000 S_OK [Src/PHTransfer.cpp:2105]|

05/25/2007 09:39:10.637 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [GetTransferBillingData]|

05/25/2007 09:39:10.637 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,XferCall_OnEntry: ICsNamedProps::SetPropString(TransferBillingExtension) to value: 1000 returned 0x00043210 S_NP_PROP_REPLACED [Src/PHTransfer.cpp:2173]|

05/25/2007 09:39:10.637 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,XferCall_OnEntry: ICsNamedProps::SetPropString(TransferBillingCallHandlerId) to value: {0bc2071a-4a4b-42d1-835f-cb9a985a1d11} returned 0x00043210 S_NP_PROP_REPLACED [Src/PHTransfer.cpp:2177]|

05/25/2007 09:39:10.637 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,XferCall_OnEntry: ICsNamedProps::SetPropLong(TransferBillingType) to value: 7002 returned 0x00000000 S_OK [Src/PHTransfer.cpp:2185]|

05/25/2007 09:39:10.637 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,3,XferCall_OnEntry: ICsNamedProps::SetPropLong(TransferBillingResult) to value: 6007 returned 0x00000000 S_OK [Src/PHTransfer.cpp:2188]|

05/25/2007 09:39:10.637 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [GetSubstitutedStr]|

05/25/2007 09:39:10.637 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Entering [ReplaceEnvVars]|

05/25/2007 09:39:10.637 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [ReplaceEnvVars]|

05/25/2007 09:39:10.637 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,ConvSub,0,Exiting [GetSubstitutedStr]|

05/25/2007 09:39:10.637 |18552,Default Switch-1-001,47E796321E084A76AF7745FD623AC089,MiuGeneral,25,Enter CAvMiuCall::TransferEx destAddr='1000' type=2=Release maxRings=4 mediaSwitch=''|

05/25/2007 09:39:11.756 |18552,Default Switch-1-001,,MiuGeneral,25,Exit CAvMiuCall::TransferEx=0x00000000=S_OK|

The call the actual MIU transfer function returned S_OK!!  Notice the extension, 1000, and the transfer type, RELEASE.

05/25/2007 09:39:11.756 |18552,Default Switch-1-001,,ConvSub,5,XferCall_OnEntry: ICsMiuCall::TransferEx( 1000, eMIU_XFER_RELEASE, 4,  ) returned 0x00000000 S_OK [Src/PHTransfer.cpp:2202]|

Since we’re done with this unsupervised transfer, we’re pusing an event that will cause us to hang up. The rest of the diags in this log are report data logging and conversation cleanup traces.

05/25/2007 09:39:11.756 |18552,Default Switch-1-001,,ConvSub,5,XferCall_OnEntry: ICsEventQueue::PushID(HANGUP_EVENT) returned 0x00000000 S_OK [Src/PHTransfer.cpp:2212]|

05/25/2007 09:39:11.756 |18552,Default Switch-1-001,,ConvSub,0,Exiting [XferCall_OnEntry]|

05/25/2007 09:39:11.756 |18552,Default Switch-1-001,,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!XferCall] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]|

05/25/2007 09:39:11.757 |18552,Default Switch-1-001,,CDE,10,CCsStateMachine::Execute : Event is [HangupEvent] [Src/CsStateMachine.cpp:165]|

05/25/2007 09:39:11.757 |18552,Default Switch-1-001,,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/PHTransfer.cde!DoHangUp] [Src/CsStateMachine.cpp:187]|

05/25/2007 09:39:11.757 |18552,Default Switch-1-001,,CDE,10, : CCustomState::OnExit : State name=[XferCall] onexit=[XferCall_OnExit] library=[libConvSub.so] [Src/CustomState.cpp:263]|

05/25/2007 09:39:11.757 |18552,Default Switch-1-001,,ConvSub,0,Entering [XferCall_OnExit]|

05/25/2007 09:39:11.757 |18552,Default Switch-1-001,,ConvSub,0,Entering [PutTransferBillingData]|

05/25/2007 09:39:11.757 |18552,Default Switch-1-001,,ConvSub,3,PutTransferBillingData: ICsNamedProps::GetPropString() found property TransferBillingDTMF = 1000.  GetPropString() returned 0x00000000 S_OK [Src/PHTransfer.cpp:1702]|

05/25/2007 09:39:11.757 |18552,Default Switch-1-001,,ConvSub,3,PutTransferBillingData: ICsNamedProps::GetPropString() found property TransferBillingBillId = .  GetPropString() returned 0x00000000 S_OK [Src/PHTransfer.cpp:1705]|

05/25/2007 09:39:11.757 |18552,Default Switch-1-001,,ConvSub,3,PutTransferBillingData: ICsNamedProps::GetPropString() found property TransferBillingObjectType = 3.  GetPropString() returned 0x00000000 S_OK [Src/PHTransfer.cpp:1708]|

05/25/2007 09:39:11.757 |18552,Default Switch-1-001,,ConvSub,3,PutTransferBillingData: ICsNamedProps::GetPropString() found property TransferBillingAlias = Marketing Transfer.  GetPropString() returned 0x00000000 S_OK [Src/PHTransfer.cpp:1711]|

05/25/2007 09:39:11.757 |18552,Default Switch-1-001,,ConvSub,3,PutTransferBillingData: ICsNamedProps::GetPropString() found property TransferBillingExtension = 1000.  GetPropString() returned 0x00000000 S_OK [Src/PHTransfer.cpp:1714]|

05/25/2007 09:39:11.757 |18552,Default Switch-1-001,,ConvSub,3,PutTransferBillingData: ICsNamedProps::GetPropString() found property TransferBillingCallHandlerId = {0bc2071a-4a4b-42d1-835f-cb9a985a1d11}.  GetPropString() returned 0x00000000 S_OK [Src/PHTransfer.cpp:1717]|

05/25/2007 09:39:11.757 |18552,Default Switch-1-001,,ConvSub,3,PutTransferBillingData: ICsNamedProps::GetPropLong() found property TransferBillingType = 7002.  GetPropLong() returned 0x00000000 S_OK [Src/PHTransfer.cpp:1720]|

05/25/2007 09:39:11.757 |18552,Default Switch-1-001,,ConvSub,3,PutTransferBillingData: ICsNamedProps::GetPropLong() found property TransferBillingResult = 6007.  GetPropLong() returned 0x00000000 S_OK [Src/PHTransfer.cpp:1725]|

05/25/2007 09:39:11.757 |18552,Default Switch-1-001,,ConvSub,0,Exiting [PutTransferBillingData]|

05/25/2007 09:39:11.757 |18552,Default Switch-1-001,,ConvSub,3,XferCall_OnExit: ICsNamedProps::RemoveProp(TransferBillingDTMF) returned 0x00000000 S_OK [Src/PHTransfer.cpp:2467]|

05/25/2007 09:39:11.757 |18552,Default Switch-1-001,,ConvSub,3,XferCall_OnExit: ICsNamedProps::RemoveProp(TransferBillingBillId) returned 0x00000000 S_OK [Src/PHTransfer.cpp:2468]|

05/25/2007 09:39:11.758 |18552,Default Switch-1-001,,ConvSub,3,XferCall_OnExit: ICsNamedProps::RemoveProp(TransferBillingObjectType) returned 0x00000000 S_OK [Src/PHTransfer.cpp:2469]|

05/25/2007 09:39:11.758 |18552,Default Switch-1-001,,ConvSub,3,XferCall_OnExit: ICsNamedProps::RemoveProp(TransferBillingAlias) returned 0x00000000 S_OK [Src/PHTransfer.cpp:2470]|

05/25/2007 09:39:11.758 |18552,Default Switch-1-001,,ConvSub,3,XferCall_OnExit: ICsNamedProps::RemoveProp(TransferBillingExtension) returned 0x00000000 S_OK [Src/PHTransfer.cpp:2471]|

05/25/2007 09:39:11.758 |18552,Default Switch-1-001,,ConvSub,3,XferCall_OnExit: ICsNamedProps::RemoveProp(TransferBillingType) returned 0x00000000 S_OK [Src/PHTransfer.cpp:2472]|

05/25/2007 09:39:11.758 |18552,Default Switch-1-001,,ConvSub,3,XferCall_OnExit: ICsNamedProps::RemoveProp(TransferBillingResult) returned 0x00000000 S_OK [Src/PHTransfer.cpp:2473]|

05/25/2007 09:39:11.758 |18552,Default Switch-1-001,,ConvSub,0,Exiting [XferCall_OnExit]|

05/25/2007 09:39:11.758 |18552,Default Switch-1-001,,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!DoHangUp] [Src/CsStateMachine.cpp:138]|

05/25/2007 09:39:11.758 |18552,Default Switch-1-001,,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/PHTransfer.cde!DoHangUp] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]|

05/25/2007 09:39:11.758 |18552,Default Switch-1-001,,CDE,10,CCsStateMachine::Execute : Event is [HangupEvent] [Src/CsStateMachine.cpp:165]|

05/25/2007 09:39:11.758 |18552,Default Switch-1-001,,CDE,10,CCsStateMachine::Execute : Next state is [NULL] [Src/CsStateMachine.cpp:187]|

05/25/2007 09:39:11.758 |18552,Default Switch-1-001,,CDE,10,CCsStateMachine::Execute : Exiting state machine. [Src/CsStateMachine.cpp:223]|

05/25/2007 09:39:11.758 |18552,Default Switch-1-001,,ConvSub,0,Entering [PHTransfer_RunExit]|

05/25/2007 09:39:11.758 |18552,Default Switch-1-001,,ConvSub,0,Entering [RemoveCallFromQueue]|

05/25/2007 09:39:11.758 |18552,Default Switch-1-001,,ConvSub,3,RemoveCallFromQueue: ICsNamedProps::GetPropLong() could not find property: lXferCookie.  GetPropLong() returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:191]|

05/25/2007 09:39:11.758 |18552,Default Switch-1-001,,ConvSub,0,Exiting [RemoveCallFromQueue]|

05/25/2007 09:39:11.758 |18552,Default Switch-1-001,,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(lXferScreeningType) returned 0x00000000 S_OK [Src/PHTransfer.cpp:224]|

05/25/2007 09:39:11.758 |18552,Default Switch-1-001,,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(vXferScreeningStream) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:225]|

05/25/2007 09:39:11.758 |18552,Default Switch-1-001,,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(bXferScreening) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:226]|

05/25/2007 09:39:11.758 |18552,Default Switch-1-001,,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(lXferType) returned 0x00000000 S_OK [Src/PHTransfer.cpp:227]|

05/25/2007 09:39:11.758 |18552,Default Switch-1-001,,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(lXferAction) returned 0x00000000 S_OK [Src/PHTransfer.cpp:228]|

05/25/2007 09:39:11.758 |18552,Default Switch-1-001,,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(bAskUserUrgent) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:229]|

05/25/2007 09:39:11.759 |18552,Default Switch-1-001,,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(lXferHoldingMode) returned 0x00000000 S_OK [Src/PHTransfer.cpp:230]|

05/25/2007 09:39:11.759 |18552,Default Switch-1-001,,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(bXferAskToHold) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:231]|

05/25/2007 09:39:11.759 |18552,Default Switch-1-001,,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(bXferIntroduce) returned 0x00000000 S_OK [Src/PHTransfer.cpp:232]|

05/25/2007 09:39:11.759 |18552,Default Switch-1-001,,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(bXferConfirm) returned 0x00000000 S_OK [Src/PHTransfer.cpp:233]|

05/25/2007 09:39:11.759 |18552,Default Switch-1-001,,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(bXferAnnounce) returned 0x00000000 S_OK [Src/PHTransfer.cpp:234]|

05/25/2007 09:39:11.759 |18552,Default Switch-1-001,,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(VoiceName) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:235]|

05/25/2007 09:39:11.759 |18552,Default Switch-1-001,,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(lXferPos) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:236]|

05/25/2007 09:39:11.759 |18552,Default Switch-1-001,,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(lXferTimeInQueue) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:237]|

05/25/2007 09:39:11.759 |18552,Default Switch-1-001,,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(lXferRequestsInQueue) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:238]|

05/25/2007 09:39:11.759 |18552,Default Switch-1-001,,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(lXferAvgTimeInQueue) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:239]|

05/25/2007 09:39:11.759 |18552,Default Switch-1-001,,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(bDoAttemptTransfer) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:240]|

05/25/2007 09:39:11.759 |18552,Default Switch-1-001,,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(strAlias) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:241]|

05/25/2007 09:39:11.759 |18552,Default Switch-1-001,,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(bXferGatherPhone) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:242]|

05/25/2007 09:39:11.759 |18552,Default Switch-1-001,,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(bXferGatherAccount) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:243]|

05/25/2007 09:39:11.759 |18552,Default Switch-1-001,,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(CallHandlerAccessID) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:244]|

05/25/2007 09:39:11.759 |18552,Default Switch-1-001,,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(bGotVoiceName) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:245]|

05/25/2007 09:39:11.759 |18552,Default Switch-1-001,,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(bTransferCompleteNeeded) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:246]|

05/25/2007 09:39:11.759 |18552,Default Switch-1-001,,ConvSub,3,PHTransfer_RunExit: ICsNamedProps::RemoveProp(CurEnt) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHTransfer.cpp:261]|

05/25/2007 09:39:11.759 |18552,Default Switch-1-001,,ConvSub,0,Exiting [PHTransfer_RunExit]|

That’s the end of our conversation and this call.

05/25/2007 09:39:11.759 |18552,Default Switch-1-001,,CDE,16,PHTransfer : CCsCDEConvBase::Run : Exiting conversation [PHTransfer] [Src/CsCDEConvBase.cpp:390]|

 

 

*******************************************************************************

Incoming call, failed login with the following traces on:

CDE

·          03 – Security

·          04 – State Machine Trace

·          14 – Errors

·          16 – Call Progress Diags

ConvSub

·          00 – Method entry/exit

·          01 – General method returns, parameter values

·          02 – Data access

·          03 – Named properties access

·          04 – MIU access

·          05 – Call progress

PhraseServer

·          03 – Information

·          05 – Phrase IDs

·          06 – Prompt file names, and audio stream info

·          07 – DTMF input

 

05/29/2007 14:09:10.706 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,Arbiter,-1,Incoming Call: Caller=1001, Called=8000, Redirect=, Reason=1, Port=Default Switch-1-001, PortsInUse=1, AnsPortsFree=1, CallGuid=77DDA5DEEF98498F9281C714EBE454E6|

 

NOTE: Since this call doesn’t differ from the previous example until the caller presses “*” to sign in, this log has been trimmed up until the point the “*” key is received…

 

05/29/2007 14:09:13.050 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [GatherDigits]|

05/29/2007 14:09:13.050 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,1,GatherDigits: put_GatherFirstDigitTimeout(0) returned 0x00000000 S_OK [Src/PHGreeting.cpp:2256]|

There it is, the “*” key during the opening greeting…

05/29/2007 14:09:13.050 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,1,GatherDigits: GatherDigits() returned 0x00045b31 S_MIU_TERM_DIGIT, digits=[*], num=[1] [Src/PHGreeting.cpp:2269]|

05/29/2007 14:09:13.050 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,GatherDigits: DTMF received [*] [Src/PHGreeting.cpp:2277]|

05/29/2007 14:09:13.050 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,GatherDigits: Matched one-key [*] [Src/PHGreeting.cpp:2304]|

05/29/2007 14:09:13.050 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,GatherDigits: Digit [*] locked [Src/PHGreeting.cpp:2333]|

05/29/2007 14:09:13.050 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [GatherDigits]|

05/29/2007 14:09:13.050 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,ProcessUserInput: GatherDigits() succeeded. Digits=[*], Menu Index =[0] [Src/PHGreeting.cpp:2650]|

05/29/2007 14:09:13.050 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,ProcessUserInput: Processing return from GatherDigits() hr=0x00041905 S_1KEY [Src/PHGreeting.cpp:2668]|

05/29/2007 14:09:13.050 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,ProcessUserInput: ICsNamedProps::SetPropString(TrafficDataAction) to value: onekey returned 0x00043210 S_NP_PROP_REPLACED [Src/PHGreeting.cpp:2817]|

05/29/2007 14:09:13.050 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,ProcessUserInput: ICsNamedProps::SetPropString(TrafficDataActionDTMF) to value: * returned 0x00043210 S_NP_PROP_REPLACED [Src/PHGreeting.cpp:2818]|

05/29/2007 14:09:13.050 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,ProcessUserInput: Take Action for Menu Entry Index=[0]! [Src/PHGreeting.cpp:2821]|

05/29/2007 14:09:13.051 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [TakeAction]|

The “*” key routes us to the SubSignIn conversation

05/29/2007 14:09:13.051 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,TakeAction: Conversation [SubSignIn] taking action [2] for ID []. [Src/PHGreeting.cpp:2042]|

05/29/2007 14:09:13.051 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,TakeAction: Termination = [SubSignIn] and Destination ID = [] [Src/PHGreeting.cpp:2135]|

05/29/2007 14:09:13.051 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,TakeAction: ICsNamedProps::GetPropVariant() found property CurEnt = .  GetPropVariant() returned 0x00000000 [Src/PHGreeting.cpp:2140]|

05/29/2007 14:09:13.051 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,TakeAction: ICsNamedProps::SetPropVariant(PreviousCurEnt) to value:  returned 0x00000000 S_OK [Src/PHGreeting.cpp:2143]|

05/29/2007 14:09:13.051 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [TakeAction]|

05/29/2007 14:09:13.051 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [ProcessUserInput]|

05/29/2007 14:09:13.051 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,PlayGreeting_OnEntry: ICsNamedProps::RemoveProp(Greeting) returned 0x00000000 S_OK [Src/PHGreeting.cpp:3979]|

05/29/2007 14:09:13.051 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,PlayGreeting_OnEntry: ICsNamedProps::RemoveProp(VoiceName) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHGreeting.cpp:3980]|

05/29/2007 14:09:13.051 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,PlayGreeting_OnEntry: ICsNamedProps::RemoveProp(CallHandlerAccessID) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHGreeting.cpp:3981]|

05/29/2007 14:09:13.051 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,PlayGreeting_OnEntry: ICsNamedProps::RemoveProp(fVoiceNameAvailable) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHGreeting.cpp:3982]|

05/29/2007 14:09:13.051 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,PlayGreeting_OnEntry: ICsNamedProps::RemoveProp(bTransferOverride) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHGreeting.cpp:3983]|

05/29/2007 14:09:13.051 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,PlayGreeting_OnEntry: ICsNamedProps::GetPropBool() could not find property: bUseErrorMsgRule.  GetPropBool() returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHGreeting.cpp:3986]|

05/29/2007 14:09:13.051 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,PlayGreeting_OnEntry: Either bUseErrorMsgRule is false or S_CALL_COMPLETE was returned [Src/PHGreeting.cpp:4003]|

05/29/2007 14:09:13.051 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [PlayGreeting_OnEntry]|

05/29/2007 14:09:13.051 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/PHGreeting.cde!PlayGreeting] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]|

05/29/2007 14:09:13.051 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : Event is [NULL] [Src/CsStateMachine.cpp:165]|

05/29/2007 14:09:13.051 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : Next state is [NULL] [Src/CsStateMachine.cpp:187]|

05/29/2007 14:09:13.052 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10, : CCustomState::OnExit : State name=[PlayGreeting] onexit=[PlayGreeting_OnExit] library=[libConvSub.so] [Src/CustomState.cpp:263]|

05/29/2007 14:09:13.052 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [PlayGreeting_OnExit]|

05/29/2007 14:09:13.052 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,PlayGreeting_OnExit: ICsNamedProps::RemoveProp(bUseErrorMsgRule) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHGreeting.cpp:4030]|

05/29/2007 14:09:13.052 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,PlayGreeting_OnExit: ICsNamedProps::GetPropBool() found property bCallHandlerData = true.  GetPropBool() returned 0x00000000 S_OK [Src/PHGreeting.cpp:4036]|

05/29/2007 14:09:13.052 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [PutCallHandlerTrafficData]|

05/29/2007 14:09:13.052 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,PutCallHandlerTrafficData: ICsNamedProps::GetPropString() found property TrafficDataDTMF = .  GetPropString() returned 0x00000000 S_OK [Src/PHGreeting.cpp:540]|

05/29/2007 14:09:13.052 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,PutCallHandlerTrafficData: ICsNamedProps::GetPropString() found property TrafficDataText = Opening Greeting.  GetPropString() returned 0x00000000 S_OK [Src/PHGreeting.cpp:543]|

05/29/2007 14:09:13.052 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,PutCallHandlerTrafficData: ICsNamedProps::GetPropString() found property TrafficDataAction = onekey.  GetPropString() returned 0x00000000 S_OK [Src/PHGreeting.cpp:546]|

05/29/2007 14:09:13.052 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,PutCallHandlerTrafficData: ICsNamedProps::GetPropString() found property TrafficDataActionDTMF = *.  GetPropString() returned 0x00000000 S_OK [Src/PHGreeting.cpp:549]|

05/29/2007 14:09:13.052 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [PutCallHandlerTrafficData]|

05/29/2007 14:09:13.053 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,PlayGreeting_OnExit: ICsNamedProps::RemoveProp(TrafficDataDTMF) returned 0x00000000 S_OK [Src/PHGreeting.cpp:4042]|

05/29/2007 14:09:13.053 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,PlayGreeting_OnExit: ICsNamedProps::RemoveProp(TrafficDataText) returned 0x00000000 S_OK [Src/PHGreeting.cpp:4043]|

05/29/2007 14:09:13.053 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,PlayGreeting_OnExit: ICsNamedProps::RemoveProp(TrafficDataAction) returned 0x00000000 S_OK [Src/PHGreeting.cpp:4044]|

05/29/2007 14:09:13.053 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,PlayGreeting_OnExit: ICsNamedProps::RemoveProp(TrafficDataActionDTMF) returned 0x00000000 S_OK [Src/PHGreeting.cpp:4045]|

05/29/2007 14:09:13.053 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,PlayGreeting_OnExit: ICsNamedProps::RemoveProp(bCallHandlerData) returned 0x00000000 S_OK [Src/PHGreeting.cpp:4046]|

05/29/2007 14:09:13.053 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [PlayGreeting_OnExit]|

05/29/2007 14:09:13.053 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : Exiting state machine. [Src/CsStateMachine.cpp:223]|

05/29/2007 14:09:13.053 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [PHGreeting_RunExit]|

05/29/2007 14:09:13.053 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,PHGreeting_RunExit: ICsNamedProps::RemoveProp(bCallBusy) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHGreeting.cpp:156]|

05/29/2007 14:09:13.053 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,PHGreeting_RunExit: ICsNamedProps::RemoveProp(lAfterGreetingAction) returned 0x00000000 S_OK [Src/PHGreeting.cpp:157]|

05/29/2007 14:09:13.053 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,PHGreeting_RunExit: ICsNamedProps::RemoveProp(bIgnoreBusyGreeting) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHGreeting.cpp:158]|

05/29/2007 14:09:13.053 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,PHGreeting_RunExit: ICsNamedProps::RemoveProp(bIgnoreInternalGreeting) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHGreeting.cpp:159]|

05/29/2007 14:09:13.053 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,PHGreeting_RunExit: ICsNamedProps::RemoveProp(bIgnoreOffHoursGreeting) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHGreeting.cpp:160]|

05/29/2007 14:09:13.053 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,PHGreeting_RunExit: ICsNamedProps::RemoveProp(bCheckSubMboxOutsiderCaller) returned 0x00000000 S_OK [Src/PHGreeting.cpp:161]|

05/29/2007 14:09:13.053 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,PHGreeting_RunExit: ICsNamedProps::RemoveProp(bCheckSubMboxNotifyOutsiderCaller) returned 0x00000000 S_OK [Src/PHGreeting.cpp:162]|

05/29/2007 14:09:13.053 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,PHGreeting_RunExit: ICsNamedProps::RemoveProp(bSendToOperWhenRec) returned 0x00000000 S_OK [Src/PHGreeting.cpp:163]|

05/29/2007 14:09:13.053 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,PHGreeting_RunExit: ICsNamedProps::RemoveProp(strDialingDomainSubEMAIL) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/PHGreeting.cpp:164]|

05/29/2007 14:09:13.053 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,PHGreeting_RunExit: ICsNamedProps::RemoveProp(bCheckRecipientServer) returned 0x00000000 S_OK [Src/PHGreeting.cpp:165]|

05/29/2007 14:09:13.053 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [PHGreeting_RunExit]|

The PHGreeting conversation shuts down

05/29/2007 14:09:13.053 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,16,PHGreeting : CCsCDEConvBase::Run : Exiting conversation [PHGreeting] [Src/CsCDEConvBase.cpp:390]|

The SubSignIn conversation starts up

05/29/2007 14:09:13.089 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,16,SubSignIn : CCsCDEConvBase::Run : Entering conversation [SubSignIn] [Src/CsCDEConvBase.cpp:124]|

05/29/2007 14:09:13.092 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [SubSignIn_RunInit]|

05/29/2007 14:09:13.092 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,SubSignIn_RunInit: ICsNamedProps::GetPropString() found property SignInCallerID = 1001.  GetPropString() returned 0x00000000 S_OK [Src/SubSignIn.cpp:74]|

First we’ll check to see if the call is coming from a know number so we don’t have to ask for the entry of an ID – the number the call came from in this case is 10011

05/29/2007 14:09:13.092 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,SubSignIn_RunInit: Tried to get Caller ID returned from named props, hr=0x00000000 S_OK, ID= [1001] [Src/SubSignIn.cpp:75]|

05/29/2007 14:09:13.092 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [GetSubscriberByDtmfIdOrPhoneWithAutoLogon]|

There’s no subscriber with a DTMF ID of 1001.

05/29/2007 14:09:13.131 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,16,No Subscriber Records found by Dtmf Access Id 1001 0x80046500 (Src/CsCallSession.cpp 217)|

05/29/2007 14:09:13.131 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,GetSubscriberByDtmfIdOrPhoneWithAutoLogon: CCsCallSession::GetSubscriberByDtmfId() returned NULL [Src/AttemptSignIn.cpp:59]|

There’s also to subscriber with an alternate extension of 1001.

05/29/2007 14:09:13.142 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,16,No Subscriber Records found by Phone Number 1001 0x80046500 (Src/CsCallSession.cpp 266)|

05/29/2007 14:09:13.142 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,GetSubscriberByDtmfIdOrPhoneWithAutoLogon: CCsCallSession::GetSubscriberByPhoneNumberWithAutoLogon() returned NULL [Src/AttemptSignIn.cpp:65]|

05/29/2007 14:09:13.142 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [GetSubscriberByDtmfIdOrPhoneWithAutoLogon]|

05/29/2007 14:09:13.142 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,SubSignIn_RunInit: GetSubscriberByDtmfIdOrPhoneWithAutoLogon( 1001 ) returned hr= 0x80004005 E_FAIL, subscriber=(nil) [Src/SubSignIn.cpp:89]|

05/29/2007 14:09:13.142 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [SubSignIn_RunInit]|

05/29/2007 14:09:13.252 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [SubSignIn_RunStart]|

05/29/2007 14:09:13.252 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,SubSignIn_RunStart: ICsNamedProps::SetPropBool(bMsgPriorityError) to value: false returned 0x00000000 S_OK [Src/SubSignIn.cpp:144]|

05/29/2007 14:09:13.252 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,SubSignIn_RunStart: ICsNamedProps::SetPropBool(bReplayMsgSummary) to value: false returned 0x00000000 S_OK [Src/SubSignIn.cpp:166]|

05/29/2007 14:09:13.252 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [SubSignIn_RunStart]|

05/29/2007 14:09:13.252 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : Starting state machine with root state [/opt/cisco/connection/share/tui/SubSignIn.cde!AnswerPhone] [Src/CsStateMachine.cpp:126]|

05/29/2007 14:09:13.252 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/SubSignIn.cde!AnswerPhone] [Src/CsStateMachine.cpp:138]|

05/29/2007 14:09:13.300 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,16, : CCsSAnswer::OnEntry : ICsMiuCall::Answer returned 0x00045B33 S_MIU_CONNECTED [Src/CsSAnswer.cpp:92]|

05/29/2007 14:09:13.300 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/SubSignIn.cde!AnswerPhone] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]|

05/29/2007 14:09:13.300 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : Event is [TrueEvent] [Src/CsStateMachine.cpp:165]|

05/29/2007 14:09:13.300 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/SubSignIn.cde!ValidateID] [Src/CsStateMachine.cpp:187]|

05/29/2007 14:09:13.300 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/SubSignIn.cde!ValidateID] [Src/CsStateMachine.cpp:138]|

05/29/2007 14:09:13.300 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10, : CCustomState::OnEntry : State name=[ValidateID] onentry=[] library=[libConvSub.so] [Src/CustomState.cpp:162]|

ValidateID_OnEntry gathers and validates the ID the caller enters

05/29/2007 14:09:13.306 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [ValidateID_OnEntry]|

05/29/2007 14:09:13.306 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,ValidateID_OnEntry: Gathering ID from the caller [Src/SubSignIn.cpp:829]|

05/29/2007 14:09:13.306 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,ValidateID_OnEntry: ICsNamedProps::GetPropBool() could not find property: bPlaySilencePromptID.  GetPropBool() returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/SubSignIn.cpp:856]|

05/29/2007 14:09:13.306 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,ValidateID_OnEntry: ICsPhrase::put_PhraseID(GetID) returned 0x00000000 S_OK [Src/SubSignIn.cpp:869]|

05/29/2007 14:09:13.306 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,1,ValidateID_OnEntry: ICsMiusCall::put_PlayTerminationDigits(1234567890*#ABCD) returned 0x00000000 S_OK [Src/SubSignIn.cpp:886]|

05/29/2007 14:09:13.306 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,ValidateID_OnEntry: Checking if ID is already in NamedProps [Src/SubSignIn.cpp:889]|

05/29/2007 14:09:13.306 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [GetIDFromNamedProps]|

05/29/2007 14:09:13.306 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,GetIDFromNamedProps: ICsNamedProps::GetPropString() found property SignInCallerID = 1001.  GetPropString() returned 0x00000000 S_OK [Src/SubSignIn.cpp:296]|

05/29/2007 14:09:13.306 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,GetIDFromNamedProps: ID from NamedProps is [1001] [Src/SubSignIn.cpp:300]|

05/29/2007 14:09:13.306 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [GetIDFromNamedProps]|

05/29/2007 14:09:13.306 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,1,ValidateID_OnEntry: GetIDFromNamedProps() returned 0x00000000 S_OK [Src/SubSignIn.cpp:897]|

05/29/2007 14:09:13.307 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,ValidateID_OnEntry: strID = 1001 [Src/SubSignIn.cpp:904]|

05/29/2007 14:09:13.307 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [GetSubscriberByDtmfIdOrPhoneWithAutoLogon]|

Call cam in from 1001, we’ve checked, and found no subscriber matching that ID

05/29/2007 14:09:13.319 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,16,No Subscriber Records found by Dtmf Access Id 1001 0x80046500 (Src/CsCallSession.cpp 217)|

05/29/2007 14:09:13.319 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,GetSubscriberByDtmfIdOrPhoneWithAutoLogon: CCsCallSession::GetSubscriberByDtmfId() returned NULL [Src/AttemptSignIn.cpp:59]|

No alternate phone numbers match 1001 for any subscribers, either.

05/29/2007 14:09:13.342 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,16,No Subscriber Records found by Phone Number 1001 0x80046500 (Src/CsCallSession.cpp 266)|

05/29/2007 14:09:13.342 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,GetSubscriberByDtmfIdOrPhoneWithAutoLogon: CCsCallSession::GetSubscriberByPhoneNumberWithAutoLogon() returned NULL [Src/AttemptSignIn.cpp:65]|

05/29/2007 14:09:13.342 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [GetSubscriberByDtmfIdOrPhoneWithAutoLogon]|

No subscriber matches the calling ID, so we’re going to ask for ID entry.

05/29/2007 14:09:13.342 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,ValidateID_OnEntry: Subscriber not found:  strID = 1001 [Src/SubSignIn.cpp:959]|

05/29/2007 14:09:13.342 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [GetIDFromUser]|

Here’s the GetID phrase with a sinlge prompt, PleaseEnterID

05/29/2007 14:09:13.342 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,3,(SingleUse.cpp) Script: SubSignIn_ENU.ps (Make) -- GetID|

05/29/2007 14:09:13.342 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,3,(SingleUse.cpp) Script: SubSignIn_ENU.ps (AddPrompt) -- PleaseEnterID|

05/29/2007 14:09:13.343 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,6,CCsPhrase::ConvertStrFileName() :         Prompt Name - /opt/cisco/connection/share/prompts/ENU/PCM/SubSignIn/AvSubSignInENU001.wav [Src/CsPhrase.cpp:1222]|

05/29/2007 14:09:13.950 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,6,CCsPhrase::Play() :     End Phrase [Src/CsPhrase.cpp:509]|

In response to the prompt, we got the following DTMF – 123#.

05/29/2007 14:09:15.281 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,7,CCsPhrase::Play() : DTMF [123#] [Src/CsPhrase.cpp:602]|

We strip off the terminating 123 and look up the user.

05/29/2007 14:09:15.281 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,GetIDFromUser: ID from the caller is [123] [Src/SubSignIn.cpp:256]|

05/29/2007 14:09:15.281 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [GetIDFromUser]|

05/29/2007 14:09:15.281 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,1,ValidateID_OnEntry: GetIDFromUser() returned: 0x00000000 S_OK [Src/SubSignIn.cpp:983]|

Absence of a failure means success…

05/29/2007 14:09:15.281 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [GetSubscriberByDtmfIdOrPhoneWithAutoLogon]|

05/29/2007 14:09:15.339 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [GetSubscriberByDtmfIdOrPhoneWithAutoLogon]|

We’ll go fetch a bunch of information about this subscriber from the database before we request a password – that’s what StoreUserInfo is all about.  You’ll see a lot of properties being set that will drive this subscriber’s conversation. Several interesting properties are called out with their own notes below.

05/29/2007 14:09:15.339 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [StoreUserInfo]|

05/29/2007 14:09:15.339 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [CheckCallRoutingRulesEnabledForSubscriber]|

05/29/2007 14:09:15.339 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,CheckCallRoutingRulesEnabledForSubscriber: Rules check: Got Subscriber [Src/SubSignIn.cpp:1494]|

05/29/2007 14:09:15.339 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,CheckCallRoutingRulesEnabledForSubscriber: Rules check: Got Subscriber's switch object id = {978dfcb1-4c56-4f21-ba73-c9066e627b56} [Src/SubSignIn.cpp:1509]|

05/29/2007 14:09:15.370 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,CheckCallRoutingRulesEnabledForSubscriber: Rules check: Got media switch [Src/SubSignIn.cpp:1525]|

05/29/2007 14:09:15.371 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,CheckCallRoutingRulesEnabledForSubscriber: Rules check: Got CCM model ID [Src/SubSignIn.cpp:1535]|

05/29/2007 14:09:15.371 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,CheckCallRoutingRulesEnabledForSubscriber: User's phone is registered with CCM, check COS. [Src/SubSignIn.cpp:1554]|

05/29/2007 14:09:15.415 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,CheckCallRoutingRulesEnabledForSubscriber: Rules are disabled. Setting bRoutingRulesEnabled off [Src/SubSignIn.cpp:1571]|

05/29/2007 14:09:15.415 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,CheckCallRoutingRulesEnabledForSubscriber: ICsNamedProps::SetPropBool(bRoutingRulesEnabled) to value: false returned 0x00000000 S_OK [Src/SubSignIn.cpp:1574]|

05/29/2007 14:09:15.415 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [CheckCallRoutingRulesEnabledForSubscriber]|

Display name: Harriet Potter

05/29/2007 14:09:15.430 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropString(MailUserDisplayName) to value: Harriet Potter returned 0x00000000 S_OK [Src/SubSignIn.cpp:363]|

05/29/2007 14:09:15.430 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropString(MailUserExtension) to value: 123 returned 0x00000000 S_OK [Src/SubSignIn.cpp:367]|

Alias: potter

05/29/2007 14:09:15.444 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropString(MailUserAlias) to value: potter returned 0x00000000 S_OK [Src/SubSignIn.cpp:392]|

05/29/2007 14:09:15.444 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropString(MailUserstrEnSecname) to value: potter returned 0x00000000 S_OK [Src/SubSignIn.cpp:395]|

05/29/2007 14:09:15.444 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropBool(Flex_bOfferMsgTypeStackMenu) to value: false returned 0x00000000 S_OK [Src/SubSignIn.cpp:398]|

05/29/2007 14:09:15.444 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropBool(UseLastNameFirst) to value: true returned 0x00000000 S_OK [Src/SubSignIn.cpp:416]|

05/29/2007 14:09:15.444 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropBool(UseExtension) to value: false returned 0x00000000 S_OK [Src/SubSignIn.cpp:419]|

05/29/2007 14:09:15.444 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropBool(UseBriefPrompts) to value: false returned 0x00000000 S_OK [Src/SubSignIn.cpp:423]|

05/29/2007 14:09:15.444 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropBool(bNewMailUser) to value: false returned 0x00000000 S_OK [Src/SubSignIn.cpp:427]|

05/29/2007 14:09:15.444 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,1,StoreUserInfo: ICsMiuCall::put_CurrentVolume(50) returned: 0x00000000 S_OK [Src/SubSignIn.cpp:442]|

05/29/2007 14:09:15.444 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,StoreUserInfo: Clock mode set = 1 [Src/SubSignIn.cpp:464]|

05/29/2007 14:09:15.444 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropLong(DtTimeFormat) to value: 1 returned 0x00000000 S_OK [Src/SubSignIn.cpp:466]|

05/29/2007 14:09:15.445 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropLong(MailUserExitAction) to value: 2 returned 0x00000000 S_OK [Src/SubSignIn.cpp:493]|

05/29/2007 14:09:15.445 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropString(MailUserExitConversation) to value: PHGreeting returned 0x00000000 S_OK [Src/SubSignIn.cpp:502]|

05/29/2007 14:09:15.445 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,StoreUserInfo: UID = [{fd848904-5dd6-4823-8e04-1afeb62cc709}] - Exit Object ID  [Src/SubSignIn.cpp:523]|

05/29/2007 14:09:15.445 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropVariant(MailUserExitObjectId) to value:  returned 0x00000000 S_OK [Src/SubSignIn.cpp:527]|

05/29/2007 14:09:15.445 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,StoreUserInfo: Subscriber conversation is 'SubMenu' [Src/SubSignIn.cpp:568]|

Conversation: SubMenu – if the subscriber used an alternate conversation, you’d see that here.

05/29/2007 14:09:15.445 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropString(SubscriberConversation) to value: SubMenu returned 0x00000000 S_OK [Src/SubSignIn.cpp:570]|

05/29/2007 14:09:15.445 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropString(SubConvAttribute) to value:  returned 0x00000000 S_OK [Src/SubSignIn.cpp:571]|

05/29/2007 14:09:15.445 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropBool(bSubAllowForward) to value: true returned 0x00000000 S_OK [Src/SubSignIn.cpp:572]|

05/29/2007 14:09:15.445 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropBool(bSubAllowReplyAll) to value: true returned 0x00000000 S_OK [Src/SubSignIn.cpp:573]|

05/29/2007 14:09:15.445 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropBool(EncryptPrivateMessages) to value: false returned 0x00000000 S_OK [Src/SubSignIn.cpp:577]|

05/29/2007 14:09:15.550 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,16,Failed to acquire CclSession 0x80046C00 (Src/CsCallSubscriber.cpp 1341)|

05/29/2007 14:09:15.555 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,16,Failed to acquire CclSession 0x80046C00 (Src/CsCallSubscriber.cpp 1341)|

05/29/2007 14:09:15.555 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropBool(bHasMeetingIntegration) to value: false returned 0x00000000 S_OK [Src/SubSignIn.cpp:579]|

05/29/2007 14:09:15.555 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropString(MailUserCallerID) to value: 1001 returned 0x00000000 S_OK [Src/SubSignIn.cpp:582]|

05/29/2007 14:09:15.555 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropString(MailUserCallID) to value: 77DDA5DEEF98498F9281C714EBE454E6 returned 0x00000000 S_OK [Src/SubSignIn.cpp:602]|

Lots of COS (Class of service) stuff…

05/29/2007 14:09:15.555 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropLong(CosMaxPrivateDlists) to value: 25 returned 0x00000000 S_OK [Src/SubSignIn.cpp:607]|

05/29/2007 14:09:15.555 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropLong(CosMaxGreetingLength) to value: 90 returned 0x00000000 S_OK [Src/SubSignIn.cpp:610]|

05/29/2007 14:09:15.555 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropBool(CosCanRecordName) to value: true returned 0x00000000 S_OK [Src/SubSignIn.cpp:613]|

05/29/2007 14:09:15.555 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropLong(CosMaxNameLength) to value: 30 returned 0x00000000 S_OK [Src/SubSignIn.cpp:616]|

05/29/2007 14:09:15.555 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropLong(CosMaxMsgLength) to value: 300 returned 0x00000000 S_OK [Src/SubSignIn.cpp:619]|

05/29/2007 14:09:15.555 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropBool(CosListInDirectoryStatus) to value: true returned 0x00000000 S_OK [Src/SubSignIn.cpp:622]|

05/29/2007 14:09:15.555 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropBool(CosCanCreatePublicDlists) to value: false returned 0x00000000 S_OK [Src/SubSignIn.cpp:628]|

05/29/2007 14:09:15.555 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropBool(CosCanSendToPublicDL) to value: true returned 0x00000000 S_OK [Src/SubSignIn.cpp:631]|

05/29/2007 14:09:15.555 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropBool(CosMoveToDeleteFolder) to value: true returned 0x00000000 S_OK [Src/SubSignIn.cpp:634]|

05/29/2007 14:09:15.555 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropLong(CosMaxMembersPVL) to value: 99 returned 0x00000000 S_OK [Src/SubSignIn.cpp:637]|

05/29/2007 14:09:15.555 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropLong(RequireSecureMsgs) to value: 4 returned 0x00000000 S_OK [Src/SubSignIn.cpp:640]|

05/29/2007 14:09:15.555 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropBool(UseDelItmFldr) to value: true returned 0x00000000 S_OK [Src/SubSignIn.cpp:647]|

05/29/2007 14:09:15.556 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropBool(CosAllowTTS) to value: false returned 0x00000000 S_OK [Src/SubSignIn.cpp:650]|

05/29/2007 14:09:15.556 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropBool(EnableEnhancedSecurity) to value: false returned 0x00000000 S_OK [Src/SubSignIn.cpp:655]|

05/29/2007 14:09:15.556 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropBool(CosUseLiveReply) to value: false returned 0x00000000 S_OK [Src/SubSignIn.cpp:658]|

05/29/2007 14:09:15.556 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropBool(MsgLocatorEnabled) to value: false returned 0x00000000 S_OK [Src/SubSignIn.cpp:661]|

05/29/2007 14:09:15.556 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [GetPlayANIPlaybackSetting]|

05/29/2007 14:09:15.556 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,GetPlayANIPlaybackSetting: ICsNamedProps::SetPropBool(SayANI) to value: false returned 0x00000000 S_OK [Src/SubSignIn.cpp:755]|

05/29/2007 14:09:15.556 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,GetPlayANIPlaybackSetting: ICsNamedProps::SetPropBool(SaySenderExt) to value: false returned 0x00000000 S_OK [Src/SubSignIn.cpp:758]|

05/29/2007 14:09:15.556 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [GetPlayANIPlaybackSetting]|

05/29/2007 14:09:15.556 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,1,StoreUserInfo: GetPlayANIPlaybackSetting() returned: 0x00000000 S_OK [Src/SubSignIn.cpp:664]|

05/29/2007 14:09:15.556 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [GetConfirmDeleteMsgOpt]|

05/29/2007 14:09:15.556 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,GetConfirmDeleteMsgOpt: ICsNamedProps::SetPropBool(bConfirmB4DeleteNewOrSavedMsg) to value: false returned 0x00000000 S_OK [Src/SubSignIn.cpp:786]|

05/29/2007 14:09:15.556 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,GetConfirmDeleteMsgOpt: ICsNamedProps::SetPropBool(bConfirmB4PurgeDeletedMsg) to value: false returned 0x00000000 S_OK [Src/SubSignIn.cpp:787]|

05/29/2007 14:09:15.556 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [GetConfirmDeleteMsgOpt]|

05/29/2007 14:09:15.556 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,1,StoreUserInfo: GetConfirmDeleteMsgOpt() returned: 0x00000000 S_OK [Src/SubSignIn.cpp:667]|

Subscriber doesn’t have a voice name recorded!

05/29/2007 14:09:15.556 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropBool(HasVoiceName) to value: false returned 0x00000000 S_OK [Src/SubSignIn.cpp:670]|

Time Zone ID: 4 – this happens to be US Pacific Time

05/29/2007 14:09:15.556 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropLong(CallerTimeZoneID) to value: 4 returned 0x00000000 S_OK [Src/SubSignIn.cpp:674]|

05/29/2007 14:09:15.556 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,StoreUserInfo: Setting caller time zone ID to [4] [Src/SubSignIn.cpp:676]|

05/29/2007 14:09:15.556 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropBool(GTMEnabled) to value: true returned 0x00000000 S_OK [Src/SubSignIn.cpp:686]|

05/29/2007 14:09:16.343 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,StoreUserInfo: CsCdlCredentialPolicy::MIN_LENGTH == 8 [Src/SubSignIn.cpp:700]|

05/29/2007 14:09:16.343 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,StoreUserInfo: ICsNamedProps::SetPropLong(MinPasswordLength) to value: 8 returned 0x00000000 S_OK [Src/SubSignIn.cpp:702]|

05/29/2007 14:09:16.343 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [StoreUserInfo]|

05/29/2007 14:09:16.343 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,1,ValidateID_OnEntry: StoreUserInfo() returned: 0x00000000 S_OK [Src/SubSignIn.cpp:1048]|

05/29/2007 14:09:16.343 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,ValidateID_OnEntry: ICsEventQueue::PushID(TRUE_EVENT) returned 0x00000000 S_OK [Src/SubSignIn.cpp:1057]|

05/29/2007 14:09:16.343 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,ValidateID_OnEntry: ICsNamedProps::SetPropString(SignInID) to value: 123 returned 0x00000000 S_OK [Src/SubSignIn.cpp:1060]|

05/29/2007 14:09:16.343 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [ValidateID_OnEntry]|

05/29/2007 14:09:16.343 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/SubSignIn.cde!ValidateID] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]|

05/29/2007 14:09:16.343 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : Event is [TrueEvent] [Src/CsStateMachine.cpp:165]|

05/29/2007 14:09:16.343 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/SubSignIn.cde!EnhancedSecurity] [Src/CsStateMachine.cpp:187]|

05/29/2007 14:09:16.343 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/SubSignIn.cde!EnhancedSecurity] [Src/CsStateMachine.cpp:138]|

05/29/2007 14:09:16.343 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10, : CCustomState::OnEntry : State name=[EnhancedSecurity] onentry=[] library=[libConvSub.so] [Src/CustomState.cpp:162]|

05/29/2007 14:09:16.343 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [EnhancedSecurity_OnEntry]|

05/29/2007 14:09:16.343 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,EnhancedSecurity_OnEntry: ICsNamedProps::RemoveProp(SignInCallerID) returned 0x00000000 S_OK [Src/SubSignIn.cpp:1241]|

05/29/2007 14:09:16.343 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [EnhancedSecurity_OnEntry]|

05/29/2007 14:09:16.344 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/SubSignIn.cde!EnhancedSecurity] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]|

05/29/2007 14:09:16.344 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : Event is [NULL] [Src/CsStateMachine.cpp:165]|

05/29/2007 14:09:16.365 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/SubSignIn.cde!LoadSubscriberData] [Src/CsStateMachine.cpp:187]|

05/29/2007 14:09:16.365 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/SubSignIn.cde!LoadSubscriberData] [Src/CsStateMachine.cpp:138]|

05/29/2007 14:09:16.382 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,16,LoadSubscriberData : CCsCDEConvBase::Run : Entering conversation [LoadSubscriberData] [Src/CsCDEConvBase.cpp:124]|

05/29/2007 14:09:16.446 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : Starting state machine with root state [/opt/cisco/connection/share/tui/LoadSubscriberData.cde!LoadSubscriberData] [Src/CsStateMachine.cpp:126]|

05/29/2007 14:09:16.446 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/LoadSubscriberData.cde!LoadSubscriberData] [Src/CsStateMachine.cpp:138]|

05/29/2007 14:09:16.446 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10, : CCustomState::OnEntry : State name=[LoadSubscriberData] onentry=[] library=[libConvSub.so] [Src/CustomState.cpp:162]|

A few more properties are gathered in LoadSubscriberData_OnEntry

05/29/2007 14:09:16.446 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [LoadSubscriberData_OnEntry]|

05/29/2007 14:09:16.446 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,LoadSubscriberData_OnEntry: ICsNamedProps::GetPropString() found property MailUserAlias = potter.  GetPropString() returned 0x00000000 S_OK [Src/LoadSubscriberData.cpp:36]|

05/29/2007 14:09:16.457 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,2,LoadSubscriberData_OnEntry: CCsIfxDbCmd::ExecuteAdHoc(SELECT SendConv FROM vw_Subscriber WHERE ObjectId = (select object_UserObjectId from vw_Alias where alias= ?)) returned 0x00000000 S_OK [Src/LoadSubscriberData.cpp:49]|

05/29/2007 14:09:16.457 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,LoadSubscriberData_OnEntry: ICsNamedProps::SetPropBool(SubSignIn_bStreamlinedSend) to value: true returned 0x00000000 S_OK [Src/LoadSubscriberData.cpp:67]|

05/29/2007 14:09:16.457 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,LoadSubscriberData_OnEntry: ICsNamedProps::SetPropBool(bUseSkipAndScan) to value: true returned 0x00000000 S_OK [Src/LoadSubscriberData.cpp:68]|

05/29/2007 14:09:16.457 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [LoadSubscriberData_OnEntry]|

05/29/2007 14:09:16.457 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/LoadSubscriberData.cde!LoadSubscriberData] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]|

05/29/2007 14:09:16.457 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : Event is [NULL] [Src/CsStateMachine.cpp:165]|

05/29/2007 14:09:16.457 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : Next state is [NULL] [Src/CsStateMachine.cpp:187]|

05/29/2007 14:09:16.458 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : Exiting state machine. [Src/CsStateMachine.cpp:223]|

05/29/2007 14:09:16.458 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,16,LoadSubscriberData : CCsCDEConvBase::Run : Exiting conversation [LoadSubscriberData] [Src/CsCDEConvBase.cpp:390]|

05/29/2007 14:09:16.458 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/SubSignIn.cde!LoadSubscriberData] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]|

05/29/2007 14:09:16.458 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : Event is [NULL] [Src/CsStateMachine.cpp:165]|

05/29/2007 14:09:16.458 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/SubSignIn.cde!ValidatePwd] [Src/CsStateMachine.cpp:187]|

Here we go to gather and validate a password.

05/29/2007 14:09:16.458 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/SubSignIn.cde!ValidatePwd] [Src/CsStateMachine.cpp:138]|

05/29/2007 14:09:16.473 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10, : CCustomState::OnEntry : State name=[ValidatePwd] onentry=[] library=[libConvSub.so] [Src/CustomState.cpp:162]|

05/29/2007 14:09:16.474 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [ValidatePwd_OnEntry]|

05/29/2007 14:09:16.474 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,ValidatePwd_OnEntry: ICsNamedProps::GetPropString() found property MailUserAlias = potter.  GetPropString() returned 0x00000000 S_OK [Src/SubSignIn.cpp:1785]|

05/29/2007 14:09:16.474 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,ValidatePwd_OnEntry: ICsNamedProps::GetPropString() found property MailUserCallerID = 1001.  GetPropString() returned 0x00000000 S_OK [Src/SubSignIn.cpp:1789]|

05/29/2007 14:09:16.474 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,ValidatePwd_OnEntry: ICsNamedProps::GetPropString() found property MailUserExtension = 123.  GetPropString() returned 0x00000000 S_OK [Src/SubSignIn.cpp:1793]|

05/29/2007 14:09:16.474 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,ValidatePwd_OnEntry: ICsNamedProps::GetPropBool() found property EnableEnhancedSecurity = false.  GetPropBool() returned 0x00000000 S_OK [Src/SubSignIn.cpp:1797]|

05/29/2007 14:09:16.474 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,ValidatePwd_OnEntry: Gathering Password from the caller [Src/SubSignIn.cpp:1806]|

05/29/2007 14:09:16.474 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,ValidatePwd_OnEntry: bNullValid = false [Src/SubSignIn.cpp:1829]|

05/29/2007 14:09:16.474 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,ValidatePwd_OnEntry: ICsNamedProps::GetPropBool() could not find property: bPlaySilencePromptPwd.  GetPropBool() returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/SubSignIn.cpp:1947]|

05/29/2007 14:09:16.474 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,ValidatePwd_OnEntry: ICsPhrse::put_PhraseID(GetSecCode) returned: 0x00000000 S_OK [Src/SubSignIn.cpp:1962]|

05/29/2007 14:09:16.474 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,1,ValidatePwd_OnEntry: ICsMiuCall::put_PlayTerminationDigits(1234567890*#ABCD) returned: 0x00000000 S_OK [Src/SubSignIn.cpp:1979]|

05/29/2007 14:09:16.474 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,ValidatePwd_OnEntry: ICsNamedProps::GetPropBool() could not find property: bSubLogInFromPhone.  GetPropBool() returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/SubSignIn.cpp:1986]|

05/29/2007 14:09:16.474 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,ValidatePwd_OnEntry: Ask the caller for a password [Src/SubSignIn.cpp:2009]|

05/29/2007 14:09:16.474 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,ValidatePwd_OnEntry: ICsNamedProps::GetPropString() could not find property: NotifyPWD.  GetPropString() returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/SubSignIn.cpp:2016]|

05/29/2007 14:09:16.474 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [GetPwdFromUser]|

05/29/2007 14:09:16.474 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,GetPwdFromUser: ICsNamedProps::GetPropBool() could not find property: bSubLogInFromPhone.  GetPropBool() returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/SubSignIn.cpp:1287]|

We make a phrase GetSecCode with one prompt, of the same name, to ask for the password.

05/29/2007 14:09:16.474 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,3,(SingleUse.cpp) Script: SubSignIn_ENU.ps (Make) -- GetSecCode|

05/29/2007 14:09:16.484 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,3,(SingleUse.cpp) Script: SubSignIn_ENU.ps (AddPrompt) -- GetSecCode|

05/29/2007 14:09:16.485 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,6,CCsPhrase::ConvertStrFileName() :         Prompt Name - /opt/cisco/connection/share/prompts/ENU/PCM/SubSignIn/AvSubSignInENU002.wav [Src/CsPhrase.cpp:1222]|

05/29/2007 14:09:17.460 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,6,CCsPhrase::Play() :     End Phrase [Src/CsPhrase.cpp:509]|

We got a password, but don’t diag the actual DTMF entered for security reasons.

05/29/2007 14:09:17.586 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,7,CCsPhrase::Play() : DTMF [***********] [Src/CsPhrase.cpp:602]|

05/29/2007 14:09:17.586 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [GetPwdFromUser]|

05/29/2007 14:09:17.586 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,1,ValidatePwd_OnEntry: GetPwdFromUser() returned: 0x00000000 S_OK [Src/SubSignIn.cpp:2027]|

05/29/2007 14:09:17.586 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,ValidatePwd_OnEntry: Validate the password [Src/SubSignIn.cpp:2082]|

05/29/2007 14:09:17.586 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [ValidatePwd]|

Our attempt to authenticate the user has failed.

05/29/2007 14:09:17.688 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDL,11,CCsCdlSubscriber::Authenticate: Cannot authenticate user: potter IMS Result Code: 1

 on line 1693 of file src/CsCdlSubscriber.cpp: Error: 0x80046505 Description: E_CDL_SP_EXEC_FAILURE|

05/29/2007 14:09:17.688 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,16,Authentication Failed for Subscriber 123 0x80046505 (Src/CsCallSubscriber.cpp 1535)|

05/29/2007 14:09:17.689 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [ValidatePwd]|

S_FALSE means the password was invalid.  Possible values for this return are:

S_OK – good password

S_FALSE – bad password

S_CDE_LOCKED_ACCOUNT – account is locked

S_CDE_EXPIRED_PASSWORD – password has expired

05/29/2007 14:09:17.689 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,1,ValidatePwd_OnEntry: ValidatePwd() returned: 0x00000001 S_FALSE [Src/SubSignIn.cpp:2085]|

05/29/2007 14:09:17.689 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [LogSignInFailure]|

05/29/2007 14:09:17.689 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,LogSignInFailure: ICsNamedProps::GetPropString() found property MailUserAlias = potter.  GetPropString() returned 0x00000000 S_OK [Src/SubSignIn.cpp:1397]|

05/29/2007 14:09:17.689 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,LogSignInFailure: ICsNamedProps::GetPropString() found property MailUserCallerID = 1001.  GetPropString() returned 0x00000000 S_OK [Src/SubSignIn.cpp:1401]|

05/29/2007 14:09:17.689 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,LogSignInFailure: ICsNamedProps::GetPropString() found property MailUserExtension = 123.  GetPropString() returned 0x00000000 S_OK [Src/SubSignIn.cpp:1405]|

This sign in failure did not result in an account lock

05/29/2007 14:09:17.689 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,LogSignInFailure: AccountLocked: No [Src/SubSignIn.cpp:1412]|

05/29/2007 14:09:17.689 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,LogSignInFailure: ICsNamedProps::GetPropObject() found property Logger.  GetPropObject() returned 0x00000000 S_OK [Src/SubSignIn.cpp:1422]|

Here’s the most English account of what happened.

05/29/2007 14:09:17.689 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,-1,-1,An invalid password entered when trying to log into a subscriber mailbox. Details - potter [123].|

05/29/2007 14:09:17.710 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [LogSignInFailure]|

We tell the caller of their failure

05/29/2007 14:09:17.710 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,3,(SingleUse.cpp) Script: SubSignIn_ENU.ps (Make) -- InvalidEntry|

05/29/2007 14:09:17.710 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,3,(SingleUse.cpp) Script: SubSignIn_ENU.ps (AddPrompt) -- ErrInvalidEntry|

05/29/2007 14:09:17.710 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,6,CCsPhrase::ConvertStrFileName() :         Prompt Name - /opt/cisco/connection/share/prompts/ENU/PCM/SubSignIn/AvSubSignInENU004.wav [Src/CsPhrase.cpp:1222]|

05/29/2007 14:09:19.160 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,6,CCsPhrase::Play() :     End Phrase [Src/CsPhrase.cpp:509]|

…then head off to ask them to reenter their password

05/29/2007 14:09:19.160 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,ValidatePwd_OnEntry: Ask the caller for a password [Src/SubSignIn.cpp:2009]|

05/29/2007 14:09:19.160 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,ValidatePwd_OnEntry: ICsNamedProps::GetPropString() could not find property: NotifyPWD.  GetPropString() returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/SubSignIn.cpp:2016]|

05/29/2007 14:09:19.160 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [GetPwdFromUser]|

05/29/2007 14:09:19.160 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,GetPwdFromUser: ICsNamedProps::GetPropBool() could not find property: bSubLogInFromPhone.  GetPropBool() returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/SubSignIn.cpp:1287]|

Once again, we build the phrase with the prompt to request a PIN

05/29/2007 14:09:19.161 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,3,(SingleUse.cpp) Script: SubSignIn_ENU.ps (Make) -- GetSecCode|

05/29/2007 14:09:19.161 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,3,(SingleUse.cpp) Script: SubSignIn_ENU.ps (AddPrompt) -- GetSecCode|

05/29/2007 14:09:19.161 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,6,CCsPhrase::ConvertStrFileName() :         Prompt Name - /opt/cisco/connection/share/prompts/ENU/PCM/SubSignIn/AvSubSignInENU002.wav [Src/CsPhrase.cpp:1222]|

05/29/2007 14:09:19.700 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,6,CCsPhrase::Play() :     End Phrase [Src/CsPhrase.cpp:509]|

Once again, we get a response, hidden in the logs for security

05/29/2007 14:09:20.126 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,7,CCsPhrase::Play() : DTMF [***********] [Src/CsPhrase.cpp:602]|

05/29/2007 14:09:20.126 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [GetPwdFromUser]|

05/29/2007 14:09:20.126 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,1,ValidatePwd_OnEntry: GetPwdFromUser() returned: 0x00000000 S_OK [Src/SubSignIn.cpp:2027]|

05/29/2007 14:09:20.126 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,ValidatePwd_OnEntry: Validate the password [Src/SubSignIn.cpp:2082]|

An attempt to validate the second password entry

05/29/2007 14:09:20.127 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [ValidatePwd]|

05/29/2007 14:09:20.143 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDL,11,CCsCdlSubscriber::Authenticate: Cannot authenticate user: potter IMS Result Code: 1

 on line 1693 of file src/CsCdlSubscriber.cpp: Error: 0x80046505 Description: E_CDL_SP_EXEC_FAILURE|

05/29/2007 14:09:20.143 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,16,Authentication Failed for Subscriber 123 0x80046505 (Src/CsCallSubscriber.cpp 1535)|

05/29/2007 14:09:20.143 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [ValidatePwd]|

05/29/2007 14:09:20.143 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,1,ValidatePwd_OnEntry: ValidatePwd() returned: 0x00000001 S_FALSE [Src/SubSignIn.cpp:2085]|

05/29/2007 14:09:20.143 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [LogSignInFailure]|

05/29/2007 14:09:20.143 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,LogSignInFailure: ICsNamedProps::GetPropString() found property MailUserAlias = potter.  GetPropString() returned 0x00000000 S_OK [Src/SubSignIn.cpp:1397]|

05/29/2007 14:09:20.143 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,LogSignInFailure: ICsNamedProps::GetPropString() found property MailUserCallerID = 1001.  GetPropString() returned 0x00000000 S_OK [Src/SubSignIn.cpp:1401]|

05/29/2007 14:09:20.143 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,LogSignInFailure: ICsNamedProps::GetPropString() found property MailUserExtension = 123.  GetPropString() returned 0x00000000 S_OK [Src/SubSignIn.cpp:1405]|

05/29/2007 14:09:20.143 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,LogSignInFailure: AccountLocked: No [Src/SubSignIn.cpp:1412]|

05/29/2007 14:09:20.143 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,LogSignInFailure: ICsNamedProps::GetPropObject() found property Logger.  GetPropObject() returned 0x00000000 S_OK [Src/SubSignIn.cpp:1422]|

A similar failure to the first attempt

05/29/2007 14:09:20.144 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,-1,-1,An invalid password entered when trying to log into a subscriber mailbox. Details - potter [123].|

05/29/2007 14:09:20.144 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [LogSignInFailure]|

05/29/2007 14:09:20.144 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,3,(SingleUse.cpp) Script: SubSignIn_ENU.ps (Make) -- InvalidEntry|

05/29/2007 14:09:20.144 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,3,(SingleUse.cpp) Script: SubSignIn_ENU.ps (AddPrompt) -- ErrInvalidEntry|

05/29/2007 14:09:20.145 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,6,CCsPhrase::ConvertStrFileName() :         Prompt Name - /opt/cisco/connection/share/prompts/ENU/PCM/SubSignIn/AvSubSignInENU004.wav [Src/CsPhrase.cpp:1222]|

05/29/2007 14:09:21.600 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,6,CCsPhrase::Play() :     End Phrase [Src/CsPhrase.cpp:509]|

05/29/2007 14:09:21.600 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,ValidatePwd_OnEntry: Ask the caller for a password [Src/SubSignIn.cpp:2009]|

05/29/2007 14:09:21.600 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,ValidatePwd_OnEntry: ICsNamedProps::GetPropString() could not find property: NotifyPWD.  GetPropString() returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/SubSignIn.cpp:2016]|

We’ll try it again

05/29/2007 14:09:21.600 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [GetPwdFromUser]|

05/29/2007 14:09:21.600 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,GetPwdFromUser: ICsNamedProps::GetPropBool() could not find property: bSubLogInFromPhone.  GetPropBool() returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/SubSignIn.cpp:1287]|

05/29/2007 14:09:21.600 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,3,(SingleUse.cpp) Script: SubSignIn_ENU.ps (Make) -- GetSecCode|

05/29/2007 14:09:21.600 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,3,(SingleUse.cpp) Script: SubSignIn_ENU.ps (AddPrompt) -- GetSecCode|

05/29/2007 14:09:21.601 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,6,CCsPhrase::ConvertStrFileName() :         Prompt Name - /opt/cisco/connection/share/prompts/ENU/PCM/SubSignIn/AvSubSignInENU002.wav [Src/CsPhrase.cpp:1222]|

05/29/2007 14:09:22.100 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,6,CCsPhrase::Play() :     End Phrase [Src/CsPhrase.cpp:509]|

05/29/2007 14:09:22.295 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,7,CCsPhrase::Play() : DTMF [***********] [Src/CsPhrase.cpp:602]|

05/29/2007 14:09:22.296 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [GetPwdFromUser]|

05/29/2007 14:09:22.296 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,1,ValidatePwd_OnEntry: GetPwdFromUser() returned: 0x00000000 S_OK [Src/SubSignIn.cpp:2027]|

05/29/2007 14:09:22.296 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,ValidatePwd_OnEntry: Validate the password [Src/SubSignIn.cpp:2082]|

05/29/2007 14:09:22.296 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [ValidatePwd]|

05/29/2007 14:09:22.323 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [ValidatePwd]|

This time, the account has been locked due to the failed password entry.

05/29/2007 14:09:22.323 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,1,ValidatePwd_OnEntry: ValidatePwd() returned: 0x00043d04 S_CDE_LOCKED_ACCOUNT [Src/SubSignIn.cpp:2085]|

05/29/2007 14:09:22.323 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,ValidatePwd_OnEntry: hr == S_CDE_LOCKED_ACCOUNT [Src/SubSignIn.cpp:2090]|

05/29/2007 14:09:22.323 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [LogSignInFailure]|

05/29/2007 14:09:22.323 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,LogSignInFailure: ICsNamedProps::GetPropString() found property MailUserAlias = potter.  GetPropString() returned 0x00000000 S_OK [Src/SubSignIn.cpp:1397]|

05/29/2007 14:09:22.323 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,LogSignInFailure: ICsNamedProps::GetPropString() found property MailUserCallerID = 1001.  GetPropString() returned 0x00000000 S_OK [Src/SubSignIn.cpp:1401]|

05/29/2007 14:09:22.323 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,LogSignInFailure: ICsNamedProps::GetPropString() found property MailUserExtension = 123.  GetPropString() returned 0x00000000 S_OK [Src/SubSignIn.cpp:1405]|

There it is – account locked = Yes

05/29/2007 14:09:22.323 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,LogSignInFailure: AccountLocked: Yes [Src/SubSignIn.cpp:1412]|

05/29/2007 14:09:22.324 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,LogSignInFailure: ICsNamedProps::GetPropObject() found property Logger.  GetPropObject() returned 0x00000000 S_OK [Src/SubSignIn.cpp:1422]|

With a very readable explanation.

05/29/2007 14:09:22.324 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,-1,-1,A subscriber account has been locked as max number of invalid login attempts exceeded. Details - potter [123].|

05/29/2007 14:09:22.324 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [LogSignInFailure]|

05/29/2007 14:09:22.324 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,5,ValidatePwd_OnEntry: ICsEventQueue::PushID(LOCKED_EVENT) returned 0x00000000 S_OK [Src/SubSignIn.cpp:2107]|

05/29/2007 14:09:22.324 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [ValidatePwd_OnEntry]|

05/29/2007 14:09:22.324 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/SubSignIn.cde!ValidatePwd] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:142]|

05/29/2007 14:09:22.324 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : Event is [LockedEvent] [Src/CsStateMachine.cpp:165]|

05/29/2007 14:09:22.325 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/SubSignIn.cde!LockedAccount] [Src/CsStateMachine.cpp:187]|

05/29/2007 14:09:22.325 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10, : CCustomState::OnExit : State name=[ValidatePwd] onexit=[ValidatePwd_OnExit] library=[libConvSub.so] [Src/CustomState.cpp:263]|

05/29/2007 14:09:22.326 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Entering [ValidatePwd_OnExit]|

05/29/2007 14:09:22.326 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,3,ValidatePwd_OnExit: ICsNamedProps::RemoveProp(bSubLogInFromPhone) returned 0x80043200 E_NP_PROP_NOT_FOUND [Src/SubSignIn.cpp:2246]|

05/29/2007 14:09:22.326 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,ConvSub,0,Exiting [ValidatePwd_OnExit]|

05/29/2007 14:09:22.326 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/SubSignIn.cde!LockedAccount] [Src/CsStateMachine.cpp:138]|

We tell the user their account has been locked

05/29/2007 14:09:22.326 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,CDE,16, : CCsSPlayPhrase::OnEntry : Couldn't find PhraseStartPosition in named props, assuming 0 [Src/CsSPlayPhrase.cpp:243]|

05/29/2007 14:09:22.326 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,3,(SingleUse.cpp) Script: SubSignIn_ENU.ps (Make) -- LockedAccount|

05/29/2007 14:09:22.326 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,3,(SingleUse.cpp) Script: SubSignIn_ENU.ps (AddPrompt) -- LockedAccount|

05/29/2007 14:09:22.351 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,6,CCsPhrase::ConvertStrFileName() :         Prompt Name - /opt/cisco/connection/share/prompts/ENU/PCM/SubSignIn/AvSubSignInENU008.wav [Src/CsPhrase.cpp:1222]|

05/29/2007 14:09:27.620 |18553,Default Switch-1-001,77DDA5DEEF98498F9281C714EBE454E6,PhraseServer,6,CCsPhrase::Play() :     End Phrase [Src/CsPhrase.cpp:509]|

Everything from here one out is the signin call winding down and returning to the main menu…

 

 

 

*******************************************************************************

*******************************************************************************

Call routing rules

*******************************************************************************

*******************************************************************************

For the following scenarions, two custom direct call routing rules have been defined:

 

Rule 1: Support Calls – route to Support Calls call handler if the call is from extension 1001 AND dialed number is 8001

Rule 2: Marketing Calls – route to Marketing Transfer call handler if the dialed number is 8001

 

Note that the default direct call routing rules are still in place, Attempt Sign In and Opening Greeting, and the two default forwarded routing rules, Attempt Forward and Opening Greeting, are also both in place.

 

Call routing scenario 1 – call from extension 1000 to voice mail port at 8001

Micro Traces ON include:

Routing Rules

·          10 – General rules component messages

·          11 – Rules creation/deletion/evaluation

 

 

Shows an incoming direct call from extension 1000 to voice mail port 8000, as well as GUID of this call for later reference

05/31/2007 08:59:31.162 |18552,Default Switch-1-002,9BACDA33120B4EF48DED58E1119E0D05,Arbiter,-1,Incoming Call: Caller=1000, Called=8001, Redirect=, Reason=1, Port=Default Switch-1-002, PortsInUse=1, AnsPortsFree=1, CallGuid=9BACDA33120B4EF48DED58E1119E0D05|

Rules evaluation begins with the first rule, at index 0.

05/31/2007 08:59:31.163 |18552,Default Switch-1-002,9BACDA33120B4EF48DED58E1119E0D05,RoutingRules,11,FindFirstTrueRule: StartIndex=[0]|

The first rule to be evaluated is the Support Calls rule

05/31/2007 08:59:31.163 |18552,Default Switch-1-002,9BACDA33120B4EF48DED58E1119E0D05,RoutingRules,11,FindFirstTrueRule: Checking rule: Support Calls at index 0|

The Support Calls rule includes a conditions that the calling number be 1001.  Since this call is from extension 1000, the condition evaluates to FALSE

05/31/2007 08:59:31.163 |18552,Default Switch-1-002,9BACDA33120B4EF48DED58E1119E0D05,RoutingRules,11,Expression CallingNumber IN 1001 evaluates to FALSE. Param CallingNumber evaluates to 1000|

And so the entire rule evaluates to FALSE

05/31/2007 08:59:31.163 |18552,Default Switch-1-002,9BACDA33120B4EF48DED58E1119E0D05,RoutingRules,11,Evaluated rule: Support Calls to FALSE on condition 0.|

The next rule, Marketing Calls, is now evaluated

05/31/2007 08:59:31.163 |18552,Default Switch-1-002,9BACDA33120B4EF48DED58E1119E0D05,RoutingRules,11,FindFirstTrueRule: Checking rule: Marketing Calls at index 1|

The Marketing Calls rule condition that the dialed number be 8001 is met, so evaluates to TRUE

05/31/2007 08:59:31.163 |18552,Default Switch-1-002,9BACDA33120B4EF48DED58E1119E0D05,RoutingRules,11,Expression DialedNumber EQ 8001 evaluates to TRUE.|

Since there is just the one condition, and it is true, the entire rule is true.

05/31/2007 08:59:31.163 |18552,Default Switch-1-002,9BACDA33120B4EF48DED58E1119E0D05,RoutingRules,11,Evaluated rule: Marketing Calls to TRUE. Found 1 bool conditions.|

The Marketing Calls rule is the rule being followed

05/31/2007 08:59:31.163 |18552,Default Switch-1-002,9BACDA33120B4EF48DED58E1119E0D05,RoutingRules,11,FindFirstTrueRule: Rule [Marketing Calls] evaluates to TRUE; Index=[1].|

 

 

*******************************************************************************

Call routing scenario 2 - call from extension 1001 to voice mail port at 8001

Micro Traces ON include:

Routing Rules

·          10 – General rules component messages

·          11 – Rules creation/deletion/evaluation

 

 

Shows an incoming direct call from extension 1001 to voice mail port 8001, as well as GUID of this call for later reference

05/31/2007 08:59:20.178 |18553,Default Switch-1-002,44889A1347A747B3910198BC6C75F84E,Arbiter,-1,Incoming Call: Caller=1001, Called=8001, Redirect=, Reason=1, Port=Default Switch-1-002, PortsInUse=1, AnsPortsFree=1, CallGuid=44889A1347A747B3910198BC6C75F84E|

Rules evaluation begins with the first rule, at index 0.

05/31/2007 08:59:20.179 |18553,Default Switch-1-002,44889A1347A747B3910198BC6C75F84E,RoutingRules,11,FindFirstTrueRule: StartIndex=[0]|

The first rule to be evaluated is the Support Calls rule

05/31/2007 08:59:20.179 |18553,Default Switch-1-002,44889A1347A747B3910198BC6C75F84E,RoutingRules,11,FindFirstTrueRule: Checking rule: Support Calls at index 0|

The Support Calls rule includes a conditions that the calling number be 1001.  Since this call is from extension 1001, the condition evaluates to TRUE

05/31/2007 08:59:20.191 |18553,Default Switch-1-002,44889A1347A747B3910198BC6C75F84E,RoutingRules,11,Expression CallingNumber IN 1001 evaluates to TRUE.|

The Support Calls rule includes a conditions that the dialed number be 8001.  Since this call is to 8001, the condition evaluates to TRUE

05/31/2007 08:59:20.191 |18553,Default Switch-1-002,44889A1347A747B3910198BC6C75F84E,RoutingRules,11,Expression DialedNumber IN 8001 evaluates to TRUE.|

Since both (2) conditions are true, the rule is true.

05/31/2007 08:59:20.191 |18553,Default Switch-1-002,44889A1347A747B3910198BC6C75F84E,RoutingRules,11,Evaluated rule: Support Calls to TRUE. Found 2 bool conditions.|

The Support Calls rule is the rule being followed

05/31/2007 08:59:20.191 |18553,Default Switch-1-002,44889A1347A747B3910198BC6C75F84E,RoutingRules,11,FindFirstTrueRule: Rule [Support Calls] evaluates to TRUE; Index=[0].|

 

 

*******************************************************************************

Call routing scenario 2 - call from extension 1000 to voice mail port at 8000

Micro Traces ON include:

Routing Rules

·          10 – General rules component messages

·          11 – Rules creation/deletion/evaluation

 

Shows an incoming direct call from extension 1000 to voice mail port 8000, as well as GUID of this call for later reference

05/31/2007 09:18:42.752 |18553,Default Switch-1-001,058CAF2C3B0F45E089AE266BCF4ECF3E,Arbiter,-1,Incoming Call: Caller=1000, Called=8000, Redirect=, Reason=1, Port=Default Switch-1-001, PortsInUse=1, AnsPortsFree=1, CallGuid=058CAF2C3B0F45E089AE266BCF4ECF3E|

Rules evaluation begins with the first rule, at index 0.

05/31/2007 09:18:42.753 |18553,Default Switch-1-001,058CAF2C3B0F45E089AE266BCF4ECF3E,RoutingRules,11,FindFirstTrueRule: StartIndex=[0]|

The first rule to be evaluated is the Support Calls rule

05/31/2007 09:18:42.753 |18553,Default Switch-1-001,058CAF2C3B0F45E089AE266BCF4ECF3E,RoutingRules,11,FindFirstTrueRule: Checking rule: Support Calls at index 0|

The Support Calls rule includes a conditions that the calling number be 1001.  Since this call is from extension 1000, the condition evaluates to FALSE

05/31/2007 09:18:42.753 |18553,Default Switch-1-001,058CAF2C3B0F45E089AE266BCF4ECF3E,RoutingRules,11,Expression CallingNumber IN 1001 evaluates to FALSE. Param CallingNumber evaluates to 1000|

And so the entire rule evaluates to FALSE

05/31/2007 09:18:42.753 |18553,Default Switch-1-001,058CAF2C3B0F45E089AE266BCF4ECF3E,RoutingRules,11,Evaluated rule: Support Calls to FALSE on condition 0.|

The next rule, Marketing Calls, is now evaluated

05/31/2007 09:18:42.753 |18553,Default Switch-1-001,058CAF2C3B0F45E089AE266BCF4ECF3E,RoutingRules,11,FindFirstTrueRule: Checking rule: Marketing Calls at index 1|

The Marketing Calls rule condition that the dialed number be 8001 is not met, so evaluates to FALSE

05/31/2007 09:18:42.753 |18553,Default Switch-1-001,058CAF2C3B0F45E089AE266BCF4ECF3E,RoutingRules,11,Expression DialedNumber EQ 8001 evaluates to FALSE. Param DialedNumber evaluates to 8000|

The Marketing Calls rule evaluates to FALSE based on the failed condition

05/31/2007 09:18:42.753 |18553,Default Switch-1-001,058CAF2C3B0F45E089AE266BCF4ECF3E,RoutingRules,11,Evaluated rule: Marketing Calls to FALSE on condition 0.|

The next rule to be checked is the Attempt Forward rule, which happens to be a Forwarded Routing Rule

05/31/2007 09:18:42.753 |18553,Default Switch-1-001,058CAF2C3B0F45E089AE266BCF4ECF3E,RoutingRules,11,FindFirstTrueRule: Checking rule: Attempt Forward at index 2|

Since this rule is a Forwared Routing Rule, and the call is a direct call, the rule does not match the call type, and is skipped

05/31/2007 09:18:42.753 |18553,Default Switch-1-001,058CAF2C3B0F45E089AE266BCF4ECF3E,RoutingRules,11,FindFirstTrueRule: Skipping rule: Attempt Forward at index 2 (non-matching type).|

The next rule to be checked is the Sign In rule, which happens to be a Forwarded Routing Rule

05/31/2007 09:18:42.753 |18553,Default Switch-1-001,058CAF2C3B0F45E089AE266BCF4ECF3E,RoutingRules,11,FindFirstTrueRule: Checking rule: Attempt Sign In at index 3|

The Attempt Sign In rule has no conditions, so evaluates to TRUE immediately

05/31/2007 09:18:42.753 |18553,Default Switch-1-001,058CAF2C3B0F45E089AE266BCF4ECF3E,RoutingRules,11,Evaluated rule: Attempt Sign In to TRUE. Found 0 bool conditions.|

The Attempt Sign In rule is the rule being followed

05/31/2007 09:18:42.753 |18553,Default Switch-1-001,058CAF2C3B0F45E089AE266BCF4ECF3E,RoutingRules,11,FindFirstTrueRule: Rule [Attempt Sign In] evaluates to TRUE; Index=[3].|