Buy or Renew
Buy or Renew
cancel
Turn on suggestions
Auto-suggest helps you quickly narrow down your search results by suggesting possible matches as you type.
Showing results for 
Search instead for 
Did you mean: 
cancel
Create a new article
2131
Views
10
Helpful
0
Comments

Unity Connection - SCCP Trace Analysis | Conversation Manager-MTA-SMTP

Luis Gomez
Cisco Employee
Cisco Employee

‎09-28-2016 08:11 AM - edited ‎03-12-2019 10:23 AM

In this scenario we will see a new message event on a CUC user, we have configured AcceptAndRelay so we will be covering:

> Conversation Manager logs for communication with CUCM

> MTA logs for message delivery

> SMTP logs for interaction with SMTP server

we have enabled and collected the following logs on CUC: 

Micro traces   (All Levels)

  •                 CuCsMgr
  •                 Notifier
  •           MTA 
  •           SMTP

Macro traces:   (All Levels)

  •           Call Flow Diagnostics
  •           Call Control (MIU) traces
  •           Conversation Traces
  •           Message Tracking Traces
  •           Traces for MWI problems

Test call information:

Caller 1113

Called 1103

Ext 1103 is set to Forward All to VM on CUCM, Voicemail box of 1103 have AcceptAndRelay to email address: “testinglab@crunity.com”

Conversation Manager logs

 

CUC process all info sent by CUCM, we can find all this info on line:

 

11:49:52.106 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuMethods,12,Enter CAvMiuCall::CallInit

 

11:49:52.107 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,Arbiter,-1,Incoming Call [callerID='1113' callerName='1113' calledID='1103' redirectingID='1103' altRedirectingID='' lastRedirectingID='1103' altLastRedirectingID='' reason=8=FwdUncond lastReason=8=FwdUncond] port=PhoneSystem-CUCM.235-1-001 portsInUse=1 ansPortsFree=19 callGuid=CC659E56D3824349A8B777E4EDAB550E

 

so, when looking for a new call event we can do a search for "Incoming Call" and look for the line that match all information of calling, called, timestamp etc.

 

Take a note also of the callGuid, this number will give you the guideline for the entire call, any other call with a different callGuid is a completely different call, this is very useful for a CUC that handles too many calls at the same time, following this callGuid properly there no change to get lost.

 

Once CUC receive and process this info it runs an "AttemptForward", this is because call was forward to CUC and not a direct call so "Forward Routing Rules" on CUC comes into play.

 

NOTE: mark the events "Entering conversation" and "Exiting conversation" so you know exactly what the system is doing on that moment.

11:49:52.110 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,16,AttemptForward : CCsCDEConvBase::Run : Entering conversation [AttemptForward] [Src/CsCDEConvBase.cpp:123]

 

To forward the Call CUC look for the RedirectingID or lastRedirectingID, only one will match, in this case the "Use Last Rather than first..." option is disabled:

 

11:49:52.110 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,ConvSub,5,GetRedirectingInfo: System.Conversations.UseLastRedirectingNumber = FALSE [Src/PHTransfer.cpp:126]

 

11:49:52.110 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,ConvSub,4,GetCalledNumber: GetRedirectingInfo() RedirectingID == 1103, return value: 0x00000000 S_OK [Src/AttemptForward.cpp:65]

 

CUC look user by DTMF, in this stage will look for Users and Call Handlers.

11:49:52.111 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,0,Entering CCsCallSession::GetCallHandlerByDtmfAccessId

 

11:49:52.111 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,1,aDtmfAccessId = 1103

 

11:49:52.131 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,1,Looking for subscriber with objectid 9e561fc1-0ff9-4f3c-a932-9148b3099b48 (Src/CsCallSession.cpp 3867)

 

11:49:52.131 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,1,Found object in session cache of type CCsCallSubscriber (Src/CsCallSession.cpp 3875)

 

11:49:52.131 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,1,Found subscriber in session cache with uid 9e561fc1-0ff9-4f3c-a932-9148b3099b48 (Src/CsCallSession.cpp 3894)

 

11:49:52.132 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,18,attrValue = xuser

 

11:49:52.132 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,18,m_strAccessId = 1103

 

Now that CUC have found the user it will forward the call to it:

 

11:49:52.132 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,ConvSub,5,AttemptForward_RunStart: Found called subscriber: {9e561fc1-0ff9-4f3c-a932-9148b3099b48} xuser 1103 [Src/AttemptForward.cpp:756]

 

Goes out from the "AttemptForward" conversation and goes into the "PHTransfer"

 

11:49:52.134 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,16,AttemptForward : CCsCDEConvBase::Run : Exiting conversation [AttemptForward] [Src/CsCDEConvBase.cpp:389]

 

11:49:52.134 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,16,PHTransfer : CCsCDEConvBase::Run : Entering conversation [PHTransfer] [Src/CsCDEConvBase.cpp:123]

 

You will see a lot of information between these events but unless you are looking for such detailed information this is not relevant for the call.

 

It transfers the call to the user and now is ready to play the greeting:

 

11:49:52.152 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,16,PHTransfer : CCsCDEConvBase::Run : Exiting conversation [PHTransfer] [Src/CsCDEConvBase.cpp:389]

 

11:49:52.152 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,16,PHGreeting : CCsCDEConvBase::Run : Entering conversation [PHGreeting] [Src/CsCDEConvBase.cpp:123]

 

So far, CUC have received the call invitation from CUCM but haven't answered yet, is in this moment when CUC is ready to take the call and play the greeting that we can see Unity sending a reply back to CUCM to actually answer the call.

 

These events where CUC is talking and negotiating with CUCM can be tracked with the "MiuSkinny" event:

 

11:49:52.165 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuMethods,17,Enter CMiuSkinnyLine::Answer

 

11:49:52.165 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,24,CAvSkinnyCallStatus::SetState New=<Answer Requested> Old=<Wait For Answer Requested> PreviousOld=<Idle>)

 

We can see CUC sending the "StationOffHookMessage" event:

 

11:49:52.165 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,13,Send StationOffHookMessage (4 bytes) no data

 

11:49:52.165 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,24,CAvSkinnyCallStatus::SetState New=<Wait For Connect> Old=<Answer Requested> PreviousOld=<Wait For Answer Requested>)

 

11:49:52.165 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,22,CAvSkinnyCallStatus::AwaitCompletion: 'CMiuSkinnyLine::Answer' waiting for completion

 

11:49:52.175 |1384,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,24,MiuSkinnyLine active: original call

 

11:49:52.178 |22660,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,24,CMiuSkinnyCall::RecvCallInfo()

 

11:49:52.178 |22660,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,24,CMiuSkinnyLine::RetrieveCallInfo to MiuCall: reason=FwdUncond lastReason=FwdUncond callerID='1113' callerName='1113' calledID='1103' redirectingID='1103' lastRedirectingID='1103' fwdLastRedirectingID=''

 

Received the "StationOpenReceiveChannelMessage"

 

11:49:52.178 |22660,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,12,Receive [Header prefix: length=136 version=18] StationOpenReceiveChannelMessage (136 bytes) conferenceID=23339728 passThruPartyID=16777269 millisecondPacketSize=20 compressionType=4=Media_Payload_G711Ulaw64k qualifierIn=[ecValue=0=Media_EchoCancellation_Off codecParamsUnion.g723BitRate=0] callReference=23339728 mRxMediaEncryptionKeyInfo.algorithmID=0=NO_ENCRYPTION mRxMediaEncryptionKeyInfo.keylen=0 mRxMediaEncryptionKeyInfo.saltlen=0 keyData=<not shown> mRxMediaEncryptionKeyInfo.isMKIPresent=0 mRxMediaEncryptionKeyInfo.keyDerivationRate=0 streamPassThroughID=0 associatedStreamID=0 RFC2833PayloadType=0 dtmfType=10 mixingMode=0 partyDirection=0 sourceIpAddr.ipAddrType=0=Ipv4 sourceIpAddr.stationIpAddr=192.168.217.235 sourcePortNumber=4000 requestedIpAddrType=0=ModeIpv4 <4 bytes not parsed>

 

11:49:52.178 |22660,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,12,Processing StationOpenReceiveChannelMessage

 

We can see also a "MediaOpenCallReference" with a call reference number; this can be matched with CUCM traces to look for this call on CUCM traces if needed.

 

11:49:52.178 |22660,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,12,MediaOpenCallReference=23339728=0x016422d0

 

11:49:52.178 |22660,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,22,CAvSkinnyCallStatus::SignalOpenReceiveChannel

 

11:49:52.178 |22660,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,Enter CMiuMedia::StartReceive

 

11:49:52.178 |22660,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,Enter CMiuMedia::OpenChannel Channel Type=Primary Audio Channel

 

11:49:52.179 |22660,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,Mixer Message send: GY_MSG_OPEN_CHN-32 len=692 msgID=32 confID=0 chnID=0 seqNo=19442 remoteIP.v6=0 remoteIP.addr.v4addr=0.0.0.0  remoteRTPPort=0 remoteRTCPPort=0 eDTMFPayloadType=0 eInitMute=0 vad=1=GY_ON eStream.codecType=0 eStream.frameSize=0 eStream.bitRate=0 eStream.payloadType=0 precedenceTOS=0 ttl=0 localIP.v6=0 localIP.addr.v4addr=0.0.0.0  localRTPPort=0 localRTCPPort=0 inDTMFPayloadType=0 dtmf=0 inInitMute=0 noCodecs=0 enableSrtp=0 inStreamKey(key)= <not shown> inStreamKey(salt)= <not shown> sessionID=0 endpointType=0=GY_EP_TYPE_USER

 

11:49:52.185 |22660,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,13,Audio Stream State: OldState=STREAM_CLOSED, NewState=STREAM_RECEIVE

 

11:49:52.185 |22660,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,Start Receive bIPV6=false RemoteAudioIPv4=0.0.0.0 lRemotePort=0 iAudioSendPacketSize=0 iSendDTMFPayload=101 iWaveFormat=0 iMediaQOS=0 strRemoteAudioIP= lRemoteVideoPort=0 bIPV6Video=false iVideoQOS=0 remoteVideoMaxBitRate=0 remoteVideoLevel=0 remoteVideoRTPPalyoad=0 lLocalPort=19956 iReceiveDTMFPayload=101 fEnableRFC2833=false fEnableSRTP=false lLocalVideoPort=0

 

11:49:52.185 |22660,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,MediaPortUsage RTP port=19956 in use by PhoneSystem-CUCM.235-1-001 objectId='589517fd-c7e6-4bc1-9640-daa26d05cf93']

 

11:49:52.185 |22660,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,Exit CMiuMedia::StartReceive=0x00000000=S_OK

 

11:49:52.185 |22660,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,19,CSkinnyWrapper::SetRTPPort 19956

 

11:49:52.185 |22660,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,22,CMiuSkinnyLine::RecvStartMediaReceive-Using receive RTP port 19956

 

11:49:52.185 |22660,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,13,Send StationOpenReceiveChannelAckMessage (36 bytes) orcStatus=0=orcOk ipAddr.ipAddrType=0=Ipv4 ipAddr.stationIpAddr=192.168.10.81 portNumber=19956 passThruPartyID=16777269

 

11:49:52.297 |30933,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,12,Receive [Header prefix: length=136 version=18] StationStartMediaTransmissionMessage (136 bytes) conferenceID=23339728 passThruPartyID=16777269 remoteIpAddr.ipAddrType=0=Ipv4 remoteIpAddr.stationIpAddr=192.168.217.235 remotePortNumber=24712 millisecondPacketSize=20 compressionType=4=Media_Payload_G711Ulaw64k qualifierOut=[precedenceValue=184 ssValue=0=Media_SilenceSuppression_Off maxFramesPerPacket=0 codecParamsUnion.g723BitRate=0] callReference=23339728 mTxMediaEncryptionKeyInfo.algorithmID=0=NO_ENCRYPTION mTxMediaEncryptionKeyInfo.keylen=0 mTxMediaEncryptionKeyInfo.saltlen=0 keyData=<not shown> mTxMediaEncryptionKeyInfo.isMKIPresent=0 mTxMediaEncryptionKeyInfo.keyDerivationRate=0 streamPassThroughID=0 associatedStreamID=0 RFC2833PayloadType=0

 

11:49:52.297 |30933,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,12,Processing StationStartMediaTransmissionMessage

 

11:49:52.297 |30933,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,24,CAvSkinnyCallStatus::SetState New=<Connected> Old=<Wait For Connect> PreviousOld=<Answer Requested>)

 

11:49:52.320 |30933,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,24,CMiuSkinnyCall::RecvConnected()

 

11:49:52.320 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuMethods,12,Exit CAvMiuCall::Answer=0x00045B33=S_MIU_CONNECTED

 

Once call is negotiated, CUC is now is total control of the call and CUCM is out of the picture.

 

CUC is ready to play the greeting:

 

11:49:52.338 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,ConvSub,5,GetActiveMessageRule: [Standard] message rule is active [Src/PHGreeting.cpp:3838]

 

11:49:52.338 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,ConvSub,5,GetActiveMessageRule: Active Greeting :- Type=Standard, PlayWhat=0, Action=4, PlayVideo=2 [Src/PHGreeting.cpp:3868]

 

11:49:52.338 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,ConvSub,5,SetPlayPromptProps: PlayWhat=0, Greeting Action=4 Phrase=SystemStandard [Src/PHGreeting.cpp:1571]

 

11:49:52.339 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,ConvSub,5,UpdateMonitorWithGreetingInfo: Playing greeting for Subscriber:  x user, 1103 [Src/PHGreeting.cpp:181]

 

Notice CUC will play the "Standard Default" greeting for this user, the audio files to open will say "Sorry, 'ObjectPresentation' is not available, please record your message after the tone"

 

NOTE: in this case the "ObjectPresentation" will be the user Extension so CUC open the audio file for 1103, in some other cases you will see that CUC opens a TTS session (Text To Speech) to read the user's Display name. 

 

11:49:52.339 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,3,(SingleUse.cpp) Script: PHGreeting_ENU.ps (Make) -- SystemStandard

 

11:49:52.339 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,3,(SingleUse.cpp) Script: PHGreeting_ENU.ps (AddPrompt) -- Sorry

 

11:49:52.339 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,3,(SingleUse.cpp) Script: PHGreeting_ENU.ps (AddPhrase) -- ObjectPresentation

 

11:49:52.339 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,3,(SingleUse.cpp) Script: Common_ENU.ps (AddPrompt) -- Extension

 

11:49:52.340 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,3,(SingleUse.cpp) Script: Common_ENU.ps (AddPrompt) -- 1_Trailing

 

11:49:52.340 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,3,(SingleUse.cpp) Script: Common_ENU.ps (AddPrompt) -- 1_Trailing

 

11:49:52.340 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,3,(SingleUse.cpp) Script: Common_ENU.ps (AddPrompt) -- 0_Trailing

 

11:49:52.340 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,3,(SingleUse.cpp) Script: Common_ENU.ps (AddPrompt) -- 3_Leading

 

11:49:52.340 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,3,(SingleUse.cpp) Script: PHGreeting_ENU.ps (AddPrompt) -- NotAvailable

 

11:49:52.340 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,3,(SingleUse.cpp) Script: PHGreeting_ENU.ps (AddPrompt) -- OkRecordNow

 

11:49:52.340 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,1,CCsPhrase::Play() :     [11:49:52 AM 07/28/2016] PhraseID - SystemStandard [Src/CsPhrase.cpp:318]

 

11:49:52.340 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,6,CCsPhrase::ConvertStrFileName() :         Prompt Name - /opt/cisco/connection/share/prompts/ENU/PCM/PHGreet/AvPHGreetENU018.wav [Src/CsPhrase.cpp:1374]

 

11:49:52.340 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,6,CCsPhrase::ConvertStrFileName() :         Prompt Name - /opt/cisco/connection/share/prompts/ENU/PCM/SkipAndScan/SkipAndScanENU002.wav [Src/CsPhrase.cpp:1374]

 

11:49:52.340 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,6,CCsPhrase::ConvertStrFileName() :         Prompt Name - /opt/cisco/connection/share/prompts/ENU/PCM/Common/Numbers/AvCommonENU201.wav [Src/CsPhrase.cpp:1374]

 

11:49:52.340 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,6,CCsPhrase::ConvertStrFileName() :         Prompt Name - /opt/cisco/connection/share/prompts/ENU/PCM/Common/Numbers/AvCommonENU201.wav [Src/CsPhrase.cpp:1374]

 

11:49:52.340 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,6,CCsPhrase::ConvertStrFileName() :         Prompt Name - /opt/cisco/connection/share/prompts/ENU/PCM/Common/Numbers/AvCommonENU200.wav [Src/CsPhrase.cpp:1374]

 

11:49:52.340 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,6,CCsPhrase::ConvertStrFileName() :         Prompt Name - /opt/cisco/connection/share/prompts/ENU/PCM/Common/Numbers/AvCommonENU050.wav [Src/CsPhrase.cpp:1374]

 

11:49:52.340 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,6,CCsPhrase::ConvertStrFileName() :         Prompt Name - /opt/cisco/connection/share/prompts/ENU/PCM/PHGreet/AvPHGreetENU019.wav [Src/CsPhrase.cpp:1374]

 

11:49:52.340 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,6,CCsPhrase::ConvertStrFileName() :         Prompt Name - /opt/cisco/connection/share/prompts/ENU/PCM/PHGreet/AvPHGreetENU016.wav [Src/CsPhrase.cpp:1374]

 

11:49:52.340 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,11,[Port PhoneSystem-CUCM.235-1-001] MiuCall Play begin

11:49:52.340 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuMethods,17,Enter CMiuSkinnyLine::Play

 

When CUC plays the greeting, we need to trace down the events following the "Mixer Message send" events, you can see the .wav file about to be opened and the Mixer sending a "GY_MSG_PLAY_FILE_START-64" to start playing:

 

11:49:52.405 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,File Name to play-/opt/cisco/connection/share/prompts/ENU/PCM/PHGreet/AvPHGreetENU018.wav

 

11:49:52.405 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,Mixer Message send: GY_MSG_PLAY_FILE_START-64 len=385 msgID=64 confID=0 chnID=49 seqNo=19445 startTimeInFile=0 maxPlayTime=0 isRepeat=0 extraParam=0 language="" contentType="" speed=0=GY_SPEED_NORMAL enableGC=0 targetGCLevel=0 validateFileHdrFmt=1 fileType[0]=0=GY_AUDIO_WAVE_FORMAT_FILE_TYPE nFiles=1

 

NOTE: if the audio file is too long you will see SCCP keepalives being exchanged with CUCM.

 

When the audio file finish, the Mixer closes the file and opens the next one:

 

11:49:53.244 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,CMiuMedia::Play-Playback completed successfully

 

11:49:53.245 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,Mixer Message send: GY_MSG_CLOSE_PLAY_FILE-66 len=20 msgID=66 confID=0 chnID=49 seqNo=19446 bytes_played_in_ms=0 startPosition=0

 

11:49:53.286 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,File Name to play-/opt/cisco/connection/share/prompts/ENU/PCM/SkipAndScan/SkipAndScanENU002.wav

 

11:49:53.286 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,Mixer Message send: GY_MSG_PLAY_FILE_START-64 len=391 msgID=64 confID=0 chnID=49 seqNo=19447 startTimeInFile=0 maxPlayTime=0 isRepeat=0 extraParam=0 language="" contentType="" speed=0=GY_SPEED_NORMAL enableGC=0 targetGCLevel=0 validateFileHdrFmt=1 fileType[0]=0=GY_AUDIO_WAVE_FORMAT_FILE_TYPE nFiles=1

 

These events will go back and forward until last audio file and played, then CUC will check for next stage and open a recording instance:

 

11:50:03.879 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,CMiuMedia::Play-Wait for Final Play Event completed successfully

 

11:50:03.879 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuMethods,15,[Port PhoneSystem-CUCM.235-1-001] MiuCall Play complete beginPositionMs=0 endPositionMs=10617 playTimeMs=10617

 

11:50:03.880 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuMethods,17,Enter CMiuSkinnyLine::GatherDigits

 

11:50:03.880 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,CMiuMedia::Gather-Waiting for Digits

 

11:50:03.880 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,CMiuMedia::Gather-Returing Digits <>

 

11:50:03.880 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,ConvSub,5,GatherDigits: No DTMF received [Src/PHGreeting.cpp:2486]

 

Conversation next state, Message record

 

11:50:03.881 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,ConvSub,5,TakeAction: Conversation [] taking action [4] for ID []. [Src/PHGreeting.cpp:2180]

 

11:50:03.962 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,10,CCsStateMachine::Execute : Event is [RecordMsgEvent] [Src/CsStateMachine.cpp:168]

 

11:50:03.965 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/PHGreeting.cde!RecordMsg] [Src/CsStateMachine.cpp:190]

 

11:50:03.989 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,13, : CCsSRecord::OnEntry : Calling ICsMiuCall::Record; lMaxRecordTime = 285000 ms, RecMode = 1 [Src/CsSRecord.cpp:404]

 

11:50:03.989 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuMethods,15,Enter CAvMiuCall::Record

 

11:50:03.989 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,11,[Port PhoneSystem-CUCM.235-1-001] MiuCall Record beginning.

 

Once again the Mixer takes place, this time to record the audio so we will see again the "Mixer Message send" event but now with state: GY_MSG_RECORD_FILE

 

11:50:03.989 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuMethods,17,Enter CMiuSkinnyLine::Record

 

11:50:03.989 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,Enter CMiuMedia::Record lMaxRecordTime=285000 lRecordMode=1 lStartPositionMs=0 fLiveRecord=0

 

11:50:03.989 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,Recording to /var/opt/cisco/connection/spool/AudioStore/WorkStreams/cuc_0f26c1cb-b931-4311-985f-a931b3b38a2b.tmp

 

11:50:03.989 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,SilenceTimeoutMs: leading=5000 trailing=3000 (0=disabled)

 

11:50:03.989 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,maximum recording duration = 285000 (ms) (RecordDefaultMaximumLength=1200000 MaxRecordTime=285000

 

11:50:03.989 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,Mixer Message send: GY_MSG_RECORD_FILE-69 len=168 msgID=69 confID=0 chnID=49 seqNo=19463 codec=1=GY_G711u annIncluded=0 enableAGC=1 targetAGCLevel=-26 playFrontBeep=1 recordingOffsetFromBeep=0 isTTYBeep=0 playLiveBeep=0 playEndingWarningBeep=0 recordingOffsetFromEnd=0 removeFrontSilence=1 removeEndingSilence=1 endingSilenceTimeout=3 maxRecordTime=285 silenceTimeout=5 startTimeInFile=0

 

in this call, ther caller pressed '#' to stop the recording, we can see the DTMF event again with a "MiuSkinny" for StationKeypadButtonMessage  cDigit=#

 

11:50:09.075 |30944,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,21,CSkinnyWrapper::ProcessData

 

11:50:09.076 |30944,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,12,Receive [Header prefix: length=16 version=18] StationKeypadButtonMessage (16 bytes) kpButton=15=skpPound lineInstance=1 callReference=23339728

 

11:50:09.076 |30944,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,12,Processing StationKeypadButtonMessage

 

11:50:09.076 |30944,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,22,CAvSkinnyCallStatus::SignalKeyPadButton: cDigit=# dwCallReference=23339728

 

11:50:09.076 |30944,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,Enter CMiuMedia::MediaEventHandler

11:50:09.076 |30944,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,CMiuMedia::MediaEventHandler-Digit (#)

 

Recording is stopped by Mixer:

 

11:50:09.076 |30944,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,13,Media State: OldState=STATE_RECORD, NewState=STATE_STOPPING

 

11:50:09.076 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,Enter CMiuMedia::StopRecordFile

 

11:50:09.076 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,Mixer Message send: GY_MSG_STOP_RECORD_FILE-70 len=12 msgID=70 confID=0 chnID=49 seqNo=19465

 

11:50:09.079 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,Enter CMiuMedia::CloseRecordFile

 

11:50:09.079 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,Mixer Message send: GY_MSG_CLOSE_RECORD_FILE-71 len=16 msgID=71 confID=0 chnID=49 seqNo=19466 removeEndRecDTMFToneLen=170

 

Once the recording is stopped and closed we can see the recording Time in Ms, in this case = recordTimeMs=4410

 

11:50:09.131 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,CMiuMedia::Record-Wait for Final Record Event completed successfully

 

11:50:09.132 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuMethods,15,[Port PhoneSystem-CUCM.235-1-001] MiuCall Record complete startPositionMs=0 endPositionMs=4410 recordTimeMs=4410

 

Process the '#' DTMF and send call to next state, Message edit:

 

11:50:09.137 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,CMiuMedia::Gather-Returing Digits <#>

 

11:50:09.138 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/PHGreeting.cde!RunEditMsg] [Src/CsStateMachine.cpp:190]

 

11:50:09.284 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,16,MessageEditing : CCsCDEConvBase::Run : Entering conversation [MessageEditing] [Src/CsCDEConvBase.cpp:123]

 

11:50:09.285 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/MessageEditing.cde!PlayAfterMessageEditMenu] [Src/CsStateMachine.cpp:190]

 

Right here CUC will play the option, to send this message press #, to edit, to cancel etc.

 

11:50:09.286 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,3,(SingleUse.cpp) Script: PHGreeting_ENU.ps (Make) -- PlayAfterMessageEditMenu_Audio

 

11:50:09.287 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,3,(SingleUse.cpp) Script: PHGreeting_ENU.ps (AddPrompt) -- ToSend

 

11:50:09.287 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,3,(SingleUse.cpp) Script: PHGreeting_ENU.ps (AddPrompt) -- EditMessageMenu

 

11:50:09.287 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,3,(SingleUse.cpp) Script: PHGreeting_ENU.ps (AddPrompt) -- ToCancel

 

11:50:09.326 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,6,CCsPhrase::ConvertStrFileName() :         Prompt Name - /opt/cisco/connection/share/prompts/ENU/PCM/PHGreet/AvPHGreetENU001.wav [Src/CsPhrase.cpp:1374]

 

11:50:09.326 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,6,CCsPhrase::ConvertStrFileName() :         Prompt Name - /opt/cisco/connection/share/prompts/ENU/PCM/PHGreet/AvPHGreetENU003.wav [Src/CsPhrase.cpp:1374]

 

11:50:09.326 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,6,CCsPhrase::ConvertStrFileName() :         Prompt Name - /opt/cisco/connection/share/prompts/ENU/PCM/PHGreet/AvPHGreetENU403.wav [Src/CsPhrase.cpp:1374]

 

11:50:09.326 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuMethods,17,Enter CMiuSkinnyLine::Play

 

11:50:09.331 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,File Name to play-/opt/cisco/connection/share/prompts/ENU/PCM/PHGreet/AvPHGreetENU001.wav

 

11:50:09.331 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,Mixer Message send: GY_MSG_PLAY_FILE_START-64 len=385 msgID=64 confID=0 chnID=49 seqNo=19467 startTimeInFile=0 maxPlayTime=0 isRepeat=0 extraParam=0 language="" contentType="" speed=0=GY_SPEED_NORMAL enableGC=0 targetGCLevel=0 validateFileHdrFmt=1 fileType[0]=0=GY_AUDIO_WAVE_FORMAT_FILE_TYPE nFiles=1

 

Once again you will see this Mixer messages going back and forward until all audio files are done but this greetings are stopped by caller again with DTMF "#"

 

11:50:13.235 |30938,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,21,CSkinnyWrapper::ProcessData

 

11:50:13.235 |30938,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,12,Receive [Header prefix: length=16 version=18] StationKeypadButtonMessage (16 bytes) kpButton=15=skpPound lineInstance=1 callReference=23339728

 

11:50:13.235 |30938,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,12,Processing StationKeypadButtonMessage

 

11:50:13.235 |30938,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,22,CAvSkinnyCallStatus::SignalKeyPadButton: cDigit=# dwCallReference=23339728

 

11:50:13.235 |30938,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,Enter CMiuMedia::MediaEventHandler

 

11:50:13.235 |30938,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,CMiuMedia::MediaEventHandler-Digit (#)

 

Stop the audio:

 

11:50:13.235 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,CMiuMedia::Play-Stop the Playback

 

11:50:13.235 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,Mixer Message send: GY_MSG_STOP_PLAY_FILE-65 len=20 msgID=65 confID=0 chnID=49 seqNo=19470 bytes_played_in_ms=0 startPosition=0

 

DTMF '#' send call to next state, Edit and send the message:

 

11:50:13.280 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuMethods,17,Enter CMiuSkinnyLine::GatherDigits

 

11:50:13.281 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,7,CCsPhrase::Play() : DTMF [#] [Src/CsPhrase.cpp:612]

 

11:50:13.281 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/MessageEditing.cde!SendMsg] [Src/CsStateMachine.cpp:190]

 

CUC process this message and add all the information about Date, Caller, Message type, Message ObjectID etc, we can follow this events with the "AddHeader" lines:

 

11:50:13.313 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CsMalUmss,14,AddHeader(Date: Thu, 28 Jul 2016 17:50:13 +0000

 

11:50:13.313 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CsMalUmss,14,AddHeader(From: "David Campos, 1113" <vm-yuser1113@unitycuc10.cravvid1.com>)

 

11:50:13.313 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CsMalUmss,14,AddHeader(To: vm-xuser1103@unitycuc10.cravvid1.com)

 

11:50:13.317 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CsMalUmss,14,AddHeader(Message-Id: <MAL.87862a17-ad80-4cc2-874b-1da0ef400b8@unitycuc10.cravvid.com>

 

11:50:13.317 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CsMalUmss,14,AddHeader(X-CiscoUnity-CallerAni: 1113)

 

11:50:13.317 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CsMalUmss,14,AddHeader(X-CiscoUnity-CallerName: y user, 1113)

 

11:50:13.317 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CsMalUmss,14,AddHeader(Subject:    Message from y user, 1113 (1113))

 

11:50:13.317 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CsMalUmss,14,AddHeader(X-CiscoUnity-MessageType: Voice)

 

11:50:13.318 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CsMalUmss,14,AddHeader(Content-Type: audio/wav; name=VoiceMessage.wav)

 

11:50:13.318 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CsMalUmss,14,AddHeader(Content-Transfer-Encoding: Base64)

 

11:50:13.318 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CsMalUmss,14,AddHeader(Content-Disposition: inline; filename=VoiceMessage.wav; voice=Voice-Message)

 

a very important line to take a note of is the "MAL.<objectID number>@domain", this is the new voicemail message objectID and we will need this number to look for this message on MTA and MailboxSync traces when is needed.

 

CUC play the audio file of "Message sent":

 

11:50:13.319 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/MessageEditing.cde!ConfirmSend] [Src/CsStateMachine.cpp:190]

 

11:50:13.319 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,0, : CCsSPlayPhrase::OnEntry : Beginning play of phrase MessageSent [Src/CsSPlayPhrase.cpp:146]

 

11:50:13.320 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,3,(SingleUse.cpp) Script: PHGreeting_ENU.ps (Make) -- MessageSent

 

11:50:13.320 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,PhraseServer,3,(SingleUse.cpp) Script: PHGreeting_ENU.ps (AddPrompt) -- MessageSent

 

11:50:13.333 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,11,[Port PhoneSystem-CUCM.235-1-001] MiuCall Play begin

 

11:50:13.333 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,File Name to play-/opt/cisco/connection/share/prompts/ENU/PCM/PHGreet/AvPHGreetENU008.wav

 

11:50:13.333 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,Mixer Message send: GY_MSG_PLAY_FILE_START-64 len=385 msgID=64 confID=0 chnID=49 seqNo=19472 startTimeInFile=0 maxPlayTime=0 isRepeat=0 extraParam=0 language="" contentType="" speed=0=GY_SPEED_NORMAL enableGC=0 targetGCLevel=0 validateFileHdrFmt=1 fileType[0]=0=GY_AUDIO_WAVE_FORMAT_FILE_TYPE nFiles=1

 

11:50:15.042 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,CMiuMedia::Play-Playback completed successfully

 

Most of the time our Trace analysis for Conversation will finish here, after the message is successfully sent we will see on this conversation logs where CUC goes out from the "MessageEditing" state:

 

11:50:15.084 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,16,MessageEditing : CCsCDEConvBase::Run : Exiting conversation [MessageEditing] [Src/CsCDEConvBase.cpp:389]

 

it goes to a transfer and and send the call to the "Good Bye" Call handler and then close the line and gets Idle again:

 

11:50:15.084 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/PHGreeting.cde!AfterMsg] [Src/CsStateMachine.cpp:190]

 

11:50:15.086 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,ConvSub,5,AfterMsg_OnEntry: After Message Action is GoTo [PHTransfer] [Src/PHGreeting.cpp:345]

 

11:50:15.087 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,16,PHTransfer : CCsCDEConvBase::Run : Entering conversation [PHTransfer] [Src/CsCDEConvBase.cpp:123]

 

11:50:15.093 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,18,attrValue = Goodbye

 

11:50:15.137 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,16,PHTransfer : CCsCDEConvBase::Run : Exiting conversation [PHTransfer] [Src/CsCDEConvBase.cpp:389]

 

11:50:15.137 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,16,PHGreeting : CCsCDEConvBase::Run : Entering conversation [PHGreeting] [Src/CsCDEConvBase.cpp:123]

 

11:50:15.137 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,18,attrValue = Goodbye

 

11:50:15.197 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,ConvSub,5,UpdateMonitorWithGreetingInfo: Playing greeting for Call Handler:  Goodbye [Src/PHGreeting.cpp:181]

 

11:50:15.198 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,11,[Port PhoneSystem-CUCM.235-1-001] MiuCall Play begin

 

11:50:15.198 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuMethods,17,Enter CMiuSkinnyLine::Play

 

11:50:15.201 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuIO,12,Mixer Message send: GY_MSG_PLAY_FILE_START-64 len=392 msgID=64 confID=0 chnID=49 seqNo=19474 startTimeInFile=0 maxPlayTime=0 isRepeat=0 extraParam=0 language="" contentType="" speed=0=GY_SPEED_NORMAL enableGC=0 targetGCLevel=0 validateFileHdrFmt=1 fileType[0]=0=GY_AUDIO_WAVE_FORMAT_FILE_TYPE nFiles=1

 

CUC received a hang up as the caller has left before CUC finished the audio play back:

 

11:50:15.668 |30662,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,12,Receive [Header prefix: length=20 version=18] StationCloseReceiveChannelMessage (20 bytes) conferenceID=23339728 passThruPartyID=16777269 callReference=23339728

 

11:50:15.668 |30662,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,12,Processing StationCloseReceiveChannelMessage

 

11:50:15.703 |30662,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuSkinny,24,CMiuSkinnyCall::RecvHangUp() - (original call)

 

VM port goes IDLE again to wait for next call event:

 

11:50:15.767 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/PHGreeting.cde!DoHangup] [Src/CsStateMachine.cpp:190]

 

11:50:15.781 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuMethods,12,Enter CAvMiu::GetCall

 

11:50:15.781 |30679,PhoneSystem-CUCM.235-1-001,CC659E56D3824349A8B777E4EDAB550E,MiuGeneral,16,Begin wait for new call -> threadsWaiting=20

 

 

This trace analysis have only the Conversation Manager portion, on MTA (Message Transfer Agent) logs we will see the message being delivered to the user mailbox and/or bringing up the SMTP to forward the message to Exchange via SMTP Relay.

 

 

 

    MTA traces

 

I've mentioned to take a note of the "MAL.<objectID number>@domain" we got from the Conversation logs when the system is sending the message, well, we will do a search on the MTA looking for this objectID to find this call events.

 

From Conversation logs, we got:  MAL.87862a17-ad80-4cc2-874b-1da0ef400b8@unitycuc10.cravvid.com so searching for it we will get this line:

 

11:50:13.324 |18880,,,MTA,14,Thread=MtaMailDelivery-6; class=CsUnityMtaMessageDelivery;Message File=/var/opt/cisco/connection/spool/UmssMtaQueue/5fecf62d-fc61-46ed-a7a1-f808438ec5b0.eml.mta has Rfc822 MessageId=MAL.87862a17-ad80-4cc2-874b-1da0ef400b8@unitycuc10.cravvid.com Sender="y user, 1113" <vm-yuser1113@unitycuc10.cravvid1.com>

 

We can follow the guideline number 18880, this number is not unique on the MTA logs but is rarely seen twice in the same timestamp so for this event that takes just a couple of milliseconds we can follow this number to see only the events for this call.

 

You will see CUC looking for the message recipient:

 

11:50:13.324 |18880,,,MTA,15,Thread=MtaMailDelivery-6; class=CsUnityMtaMessage;validateSenderIsSubscriber: localPart=vm-yuser1113, domainPart=unitycuc10.cravvid1.com, localDomain=unitycuc10.cravvid1.com

 

11:50:13.339 |18880,,,MTA,15,Thread=MtaMailDelivery-6; class=CsUnityMtaMessage;Number of recipients in the Message=1 (Rfc822 MessageId=MAL.87862a17-ad80-4cc2-874b-1da0ef400b8@unitycuc10.cravvid.com)

 

11:50:13.339 |18880,,,MTA,15,Thread=MtaMailDelivery-6; class=CsUnityMtaMessage;Resolve Message Recipient: vm-xuser1103@unitycuc10.cravvid1.com ndr reason: success

 

Then, it will process the action to take; in this case will do "AcceptAndRelay"

 

11:50:13.361 |18880,,,MTA,15,Thread=MtaMailDelivery-6; class=CsUnityMtaMessageHandlingProperties;voicemail message action=AcceptAndRelay effective=AcceptAndRelay

 

11:50:13.362 |18880,,,MTA,15,Thread=MtaMailDelivery-6; class=CsUnityMtaMessage;Relay message for 'vm-xuser1103@unitycuc10.cravvid1.com' (subscriber.objectid=9e561fc1-0ff9-4f3c-a932-9148b3099b48) to 'testinglab@CRUnity.com'

 

This means, CUC will save the message on the local mailbox for this user and will create a copy of it to be sent to the SMTP smart host, looking to be delivered to a final email destination =  'testinglab@CRUnity.com'

 

11:50:13.371 |18880,,,MTA,15,Thread=MtaMailDelivery-6; class=CsUnityMtaMessage;Relaying to relayaddress='testinglab@CRUnity.com'

 

 

Before that, the system processes the local message recipient:

 

11:50:13.376 |18880,,,MTA,15,Thread=MtaMailDelivery-6; class=CsUnityMtaMessage;Original Recipient #1 of the Message=vm-xuser1103@unitycuc10.cravvid1.com (Rfc822 MessageId=MAL.87862a17-ad80-4cc2-874b-1da0ef400b8@unitycuc10.cravvid.com)

 

11:50:13.377 |18880,,,MTA,15,Thread=MtaMailDelivery-6; class=CsUnityMtaLocalDelivery;Deliver Message to recipients on Database : UnityMbxDb1 (Rfc822 MessageId=MAL.87862a17-ad80-4cc2-874b-1da0ef400b8@unitycuc10.cravvid.com) Sender : vm-yuser1113@unitycuc10.cravvid1.com

 

11:50:13.431 |18880,,,MTA,14,Thread=MtaMailDelivery-6; class=CsUnityMtaLocalDelivery;Deliver a message to local recipients

 

Open the "UnityMbxDb1", this is the Mailstore Database:

 

11:50:13.676 |18880,,,MTA,15,Thread=MtaMailDelivery-6; class=CsUnityMtaLocalDelivery;Opened connection to UnityMbxDb1

 

Add the recipient and deliver the message:

 

11:50:13.700 |18880,,,MTA,15,Thread=MtaMailDelivery-6; class=CsUnityMtaLocalDelivery;Adding recipient for the Message Id:fc317d15-05b7-4dd5-91ac-687ca73df0ad. Recipient Email=vm-xuser1103@unitycuc10.cravvid1.com. Recipient Id=06a9bcb0-9f92-4771-999f-b80383bd3837

 

11:50:13.771 |18880,,,MTA,14,Thread=MtaMailDelivery-6; class=CsUnityMtaLocalDelivery;Message Delivered to Recipient. SMTP Addreess=vm-xuser1103@unitycuc10.cravvid1.com mailbox Id=06a9bcb0-9f92-4771-999f-b80383bd3837

 

Close the "UnityMbxDb1"

 

11:50:13.796 |18880,,,MTA,15,Thread=MtaMailDelivery-6; class=CsUnityMtaLocalDelivery;Closing connection to UnityMbxDb1

 

For the relay message, it notifies the SMTP so we will see those events on the SMTP traces:

 

11:50:14.038 |18880,,,MTA,15,Thread=MtaMailDelivery-6; class=CsUnityMtaCreateSmtpRelayMessage;Create STMP Message. File Name=/var/opt/cisco/connection/spool/UmssMtaTemp/CUMTA.0c4b4d24-f3b1-4c68-acc5-f7fb592c2956@UnityCUC10.txt

 

11:50:14.722 |18880,,,MTA,15,Thread=MtaMailDelivery-6; class=CsUnityMtaForeignOut;!!! Notify SMTP Server !!!

 

Finished the message delivery and then mark it as successful: 

 

11:50:14.722 |18880,,,MTA,15,Thread=MtaMailDelivery-6; class=CsUnityMtaDelivery;Finish Message Delivery for fileName=/var/opt/cisco/connection/spool/UmssMtaQueue/5fecf62d-fc61-46ed-a7a1-f808438ec5b0.eml.mta Status=0

 

11:50:14.722 |18880,,,MTA,15,Thread=MtaMailDelivery-6; class=CsUnityMtaMessageHandler;Message delivery Status!! File=/var/opt/cisco/connection/spool/UmssMtaQueue/5fecf62d-fc61-46ed-a7a1-f808438ec5b0.eml.mta; Status=0; retry Count=0 retry limit=3

 

11:50:14.722 |18880,,,MTA,14,Thread=MtaMailDelivery-6; class=CsUnityMtaMessageHandler;Message Delivered successfully!! File Name=/var/opt/cisco/connection/spool/UmssMtaQueue/5fecf62d-fc61-46ed-a7a1-f808438ec5b0.eml.mta

 

 

 

 

    SMTP traces

 

The MTA process has notified the SMTP, so from SMTP logs we will see the message being sent to the smart host.

 

In this case, the Smart host on CUC is configured as 192.168.217.100 this is an Exchange 2010 server acting as Smart Host.

 

 

Once again we can search for the "MAL.<objectID number>@domain" but also we can look for the relay address we found on the MTA = 'testinglab@CRUnity.com'

 

We can also follow the threat as guideline (in this case 18720 ) for the events of this call in specific.

 

 

When sending message, CUC gets connected with SMTP Smart Host on port 25:

 

11:50:14.725 |18720,,,SMTP,18,Thread=SmtpClient-Delivery-2; class=com.cisco.unity.smtp.client.CsUnitySmtpC_MsgDelivery;Sending message file: /var/opt/cisco/connection/smtp/default/pickup/CUMTA.0c4b4d24-f3b1-4c68-acc5-f7fb592c2956@UnityCUC10.txt to testinglab@CRUnity.com

 

11:50:14.725 |18720,,,SMTP,15,Thread=SmtpClient-Delivery-2; class=com.cisco.unity.smtp.client.CsUnitySmtpC_MsgDelivery;hostAddress: 192.168.217.100, resolved to ip: /192.168.217.100 port: 25

 

11:50:14.725 |18720,,,SMTP,15,Thread=SmtpClient-Delivery-2; class=com.cisco.unity.smtp.client.CsUnitySmtpConnector;Connecting to SMTP server. Remote IP=192.168.217.100 Remote Port=25

 

11:50:17.732 |18720,,,SMTP,15,Thread=SmtpClient-Delivery-2; class=com.cisco.unity.smtp.client.CsUnitySmtpConnector;Connected to SMTP server. Remote IP=192.168.217.100 Remote Port=25 smtpResponseTimeoutSec=14

 

Once it gets connected, we can identify the CUC messages with "Unity SMTP Client" and the Smart Host messages with "SMTP Server", so basically "Unity SMTP Client" is unity talking and "SMTP Server" is Exchange talking.

 

11:50:22.740 |18720,,,SMTP,15,Thread=SmtpClient-Delivery-2; class=com.cisco.unity.smtp.client.CsUnitySmtpConnector;SMTP Server: 220 WIN-5T7BL13V7G8.CRUnity.com Microsoft ESMTP MAIL Service ready at Thu, 28 Jul 2016 11:43:02 -0700

 

11:50:22.741 |18720,,,SMTP,15,Thread=SmtpClient-Delivery-2; class=com.cisco.unity.smtp.client.CsUnitySmtpConnector;Unity SMTP Client: EHLO UnityCUC10.cravvid.com

 

11:50:22.742 |18720,,,SMTP,15,Thread=SmtpClient-Delivery-2; class=com.cisco.unity.smtp.client.CsUnitySmtpConnector;SMTP Server: 250-WIN-5T7BL13V7G8.CRUnity.com Hello [192.168.10.81]

 

CUC present the message with FROM and TO, Exchange respond with OK

 

11:50:22.742 |18720,,,SMTP,15,Thread=SmtpClient-Delivery-2; class=com.cisco.unity.smtp.client.CsUnitySmtpConnector;Unity SMTP Client: MAIL FROM:<vm-yuser1113@unitycuc10.cravvid1.com>

 

11:50:22.743 |18720,,,SMTP,15,Thread=SmtpClient-Delivery-2; class=com.cisco.unity.smtp.client.CsUnitySmtpConnector;SMTP Server: 250 2.1.0 Sender OK

 

Most of the time when there a case reporting this message does not reach the email destination we will see an error here, when CUC present the Recipient the SMTP respond with a "550 5.7.1 Unable to relay" or any other error, this means the SMTP is rejecting the message and the issue needs to be addressed by the Exchange/Smart Host administrator

 

11:50:22.744 |18720,,,SMTP,15,Thread=SmtpClient-Delivery-2; class=com.cisco.unity.smtp.client.CsUnitySmtpConnector;Unity SMTP Client: RCPT TO:<testinglab@CRUnity.com>

11:50:22.744 |18720,,,SMTP,15,Thread=SmtpClient-Delivery-2; class=com.cisco.unity.smtp.client.CsUnitySmtpConnector;SMTP Server: 250 2.1.5 Recipient OK

 

 

11:50:22.744 |18720,,,SMTP,15,Thread=SmtpClient-Delivery-2; class=com.cisco.unity.smtp.client.CsUnitySmtpConnector;Unity SMTP Client: DATA

 

SMTP here is sending this message to a queue for delivery, CUC complete its part and now the message delivery is in hands of the SMTP smart host.

 

11:50:22.983 |18720,,,SMTP,15,Thread=SmtpClient-Delivery-2; class=com.cisco.unity.smtp.client.CsUnitySmtpConnector;SMTP Server: 250 2.6.0 <MAL.87862a17-ad80-4cc2-874b-1da0ef400b8@unitycuc10.cravvid.com> [InternalId=165] Queued mail for delivery

 

CUC disconnect and mark the message as successfully delivery:

 

11:50:22.983 |18720,,,SMTP,15,Thread=SmtpClient-Delivery-2; class=com.cisco.unity.smtp.client.CsUnitySmtpConnector;Unity SMTP Client: QUIT

 

11:50:22.986 |18720,,,SMTP,15,Thread=SmtpClient-Delivery-2; class=com.cisco.unity.smtp.client.CsUnitySmtpConnector;SMTP Server: 221 2.0.0 Service closing transmission channel

 

11:50:22.986 |18720,,,SMTP,15,Thread=SmtpClient-Delivery-2; class=com.cisco.unity.smtp.client.CsUnitySmtpC_MsgDelivery;Host Name=192.168.217.100 Message ID=<MAL.87862a17-ad80-4cc2-874b-1da0ef400b8@unitycuc10.cravvid.com> Message delivered to:testinglab@CRUnity.com

 

11:50:22.986 |18720,,,SMTP,15,Thread=SmtpClient-Delivery-2; class=com.cisco.unity.smtp.client.CsUnitySmtpC_MsgDelivery;Stop: Processing Message. Path=/var/opt/cisco/connection/smtp/default/pickup/CUMTA.0c4b4d24-f3b1-4c68-acc5-f7fb592c2956@UnityCUC10.txt status: completed

 

 

 

As we can see, we can trace down the new voicemail using the "MAL.<objectID number>@domain" on Coversation, MTA and SMPT traces, we can also search on Mailbox Sync traces when Single Inbox is in place, I’ll get also a full trace analysis like this for Unified Messaging to share with you.

 

 

 

 

 

I hope you can find this document useful for your CUC trace analysis.

Best regards,

Luis Gomez

luisgom@cisco.com

Labels:
Getting Started

Find answers to your questions by entering keywords or phrases in the Search bar above. New here? Use these resources to familiarize yourself with the community:

Customers Also Viewed These Support Documents