This document has annotated diags for the following scenarios
MWI failure due to MWI configured with incorrect
switch...................................................... 1
MWI failure due to ports not configured for MWI.................................................................. 2
SMTP Notification Failure Scenario....................................................................................... 5
Normal Message Delivery and Retrieval................................................................................. 8
Scenario where message cannot be delivered due to sender not found.................................... 9
(MWI Macro trace)
In this case the MWI
was configured for the “Default Switch”.
CuNotifier diag file
From this file we see
that there was some failure setting the lamp.
The first line indicates that a resync has been requested for Bailey
Bell and further down we see that it is a “hard” resync (reset the lamp status
even if it appears to be already correct
which in this case it’s not correct).
The last line shows that there was a failure. We need to look at the CuCsMgr
diag file to find out more about the failure.
06/20/2007
12:26:25.939 |9050,,,Notifier,21,Read from NotifyQ: NOTIFYQ_ACTION_FULL_RESYNC_MAILUSER Bailey Bell MailboxObjectId=7ba4a3f2-84e7-425f-bee6-e5a981a0822a |
06/20/2007
12:26:25.939 |9047,,,Notifier,21,MessageStoreMonitor
NOTIFYQ_ACTION_FULL_RESYNC_MAILUSER Bailey Bell MailboxObjectId=7ba4a3f2-84e7-425f-bee6-e5a981a0822a
|
06/20/2007
12:26:25.940 |9047,,,Notifier,21,Handling ResyncMailbox event with flags Database-MsgStore-HardMWI
for mailbox objectid=7ba4a3f2-84e7-425f-bee6-e5a981a0822a|
06/20/2007
12:26:26.449 |9050,,,Notifier,21,Read from NotifyQ: NOTIFYQ_ACTION_MSG_COUNTS Bailey Bell MailboxObjectId=7ba4a3f2-84e7-425f-bee6-e5a981a0822a |
06/20/2007
12:26:26.449 |9050,,,Notifier,21,Read from NotifyQ: + message seq#=36
message counts=0,1,0 seconds ago
received=0|
06/20/2007
12:26:26.450 |9047,,,Notifier,21,MessageStoreMonitor
NOTIFYQ_ACTION_MSG_COUNTS Bailey Bell MailboxObjectId=7ba4a3f2-84e7-425f-bee6-e5a981a0822a
|
06/20/2007
12:26:26.450 |9047,,,Notifier,21,MessageStoreMonitor +
message seq#=36 message counts=0,1,0 seconds ago
received=0|
06/20/2007
12:26:26.450 |9047,,,Notifier,21,Bailey Bell: MessageCounts event seq#=36
counts=0,1,0
|
06/20/2007
12:26:26.450 |9047,,,Notifier,12,Bailey Bell: evaluate MWI - hard lamp resync ON (resync) mwi extension=2031|
06/20/2007
12:26:26.450 |9047,,,Notifier,24,processMessageCounts
for Bailey Bell seq#=36 counts=0,1,0 , no resync
needed|
06/20/2007
12:26:26.485 |9048,,,Notifier,21,ResultMonitor
NOTIFYQ_ACTION_MWION_FAILURE Bailey Bell MailboxObjectId=7ba4a3f2-84e7-425f-bee6-e5a981a0822a
b9ae93f1-0166-4509-aef8-39b69e75c1de|
06/20/2007
12:26:26.485 |9048,,,Notifier,12,Bailey Bell: MWI
(ON) failed for mwi extension =2031|
CuCsMgr diag file
We look at the lines
in this file for the time corresponding to the MWI attempt. The first line shows Bailey Bell’s name and
further down we see his DTMF access id and MWI extension. There is also a spurious error about not
loading a SubscriberObjectId which can be
ignored. The last line shows the reason
for the MWI failure: the switch being used has no ports.
06/20/2007
12:26:26.483 |31640,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found display name (subscriber): Bailey Bell|
06/20/2007
12:26:26.483 |31640,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found device name: MWI-1|
06/20/2007
12:26:26.483 |31640,,,Notifier,12,Error getting value
of named property SubscriberObjectId for Bailey Bell.
HRESULT:80004005|
06/20/2007
12:26:26.483 |31640,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found display dtmf: 456|
06/20/2007
12:26:26.483 |31640,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found do report flag: true|
06/20/2007
12:26:26.483 |31640,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found voice count: 1|
06/20/2007
12:26:26.484 |31640,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found urgent count: 0|
06/20/2007
12:26:26.484 |31640,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found email count: 0|
06/20/2007
12:26:26.484 |31640,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found fax count: 0|
06/20/2007
12:26:26.484 |31640,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found initial delay: 0|
06/20/2007
12:26:26.484 |31640,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found result context: '(null)'|
06/20/2007
12:26:26.484 |31640,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found switch objectid:
'492b2cbd-f44b-498f-a5f4-1af5eb6eb4c3'|
06/20/2007
12:26:26.484 |31640,,,Notifier,12,CCsMWIDevice::TransferPropertiesToTask
found mwi on/off type 2|
06/20/2007
12:26:26.484 |31640,,,Notifier,12,CCsMWIDevice::TransferPropertiesToTask
found mwi extension 2031|
06/20/2007
12:26:26.484 |31640,,,Notifier,12,CCsMWIDevice::TransferPropertiesToTask
found mwi port object id |
06/20/2007
12:26:26.484 |31640,,,Notifier,12,CCsMWIDevice::TransferPropertiesToTask
found mwi object id
b9ae93f1-0166-4509-aef8-39b69e75c1de|
06/20/2007
12:26:26.484 |31640,,,Notifier,12,CCsMWIDevice::TransferPropertiesToTask
found suspend update flag 0|
06/20/2007
12:26:26.484 |31640,,,Notifier,12,Failed MWI for mailuser=Bailey Bell due to absence of
switch 492b2cbd-f44b-498f-a5f4-1af5eb6eb4c3 (possibly due to no ports
configured for the switch)|
(MWI Macro trace)
CuCsMgr diag file
We see Bailey Bell’s
name, extension, and MWI extension followed by a message telling us that no
ports are configured for MWI and the MWI fails.
06/20/2007
12:31:37.272 |31639,,,Notifier,12,CConfigData::GetValue(System.Notifier.RetriesOnFailure) returned 5|
06/20/2007
12:31:37.273 |31639,,,Notifier,12,CConfigData::GetValue(System.Notifier.FailureRetryIntervalSeconds) returned 5|
06/20/2007
12:31:37.273 |31639,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found display name (subscriber): Bailey Bell|
06/20/2007
12:31:37.273 |31639,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found device name: MWI-1|
06/20/2007
12:31:37.273 |31639,,,Notifier,12,Error getting value
of named property SubscriberObjectId for Bailey Bell.
HRESULT:80004005|
06/20/2007
12:31:37.273 |31639,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found display dtmf: 456|
06/20/2007
12:31:37.273 |31639,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found do report flag: true|
06/20/2007
12:31:37.273 |31639,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found voice count: 1|
06/20/2007
12:31:37.273 |31639,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found urgent count: 0|
06/20/2007
12:31:37.273 |31639,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found email count: 0|
06/20/2007
12:31:37.273 |31639,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found fax count: 0|
06/20/2007
12:31:37.273 |31639,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found initial delay: 0|
06/20/2007
12:31:37.273 |31639,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found result context: '(null)'|
06/20/2007
12:31:37.273 |31639,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found switch objectid:
'e5a9d154-169a-48fa-87ff-5a1282b5f2c1'|
06/20/2007
12:31:37.273 |31639,,,Notifier,12,CCsMWIDevice::TransferPropertiesToTask
found mwi on/off type 2|
06/20/2007
12:31:37.273 |31639,,,Notifier,12,CCsMWIDevice::TransferPropertiesToTask
found mwi extension 2031|
06/20/2007
12:31:37.273 |31639,,,Notifier,12,CCsMWIDevice::TransferPropertiesToTask
found mwi port object id |
06/20/2007
12:31:37.273 |31639,,,Notifier,12,CCsMWIDevice::TransferPropertiesToTask
found mwi object id
b9ae93f1-0166-4509-aef8-39b69e75c1de|
06/20/2007
12:31:37.274 |31639,,,Notifier,12,CCsMWIDevice::TransferPropertiesToTask
found suspend update flag 0|
06/20/2007
12:31:37.274 |31639,,,-1,-1,No ports found with MWI capabilities. No
message waiting lamp dialouts will occur. If this is
unexpected, use Unity Connection Administration to change the port
capabilities. Note that serial and some digital MWI do not require dialouts.|
06/20/2007
12:31:37.275 |31639,,,Notifier,12,Failed MWI for mailuser=Bailey Bell due to lack of
voice ports configured for mwi|
When all is corrected,
the CuCsMgr diags show the
success.
Again, we see Bailey
Bell’s name, extension, and MWI extension.
Further down we see the RESYNC ON starting. There are lots of low-level diags that should help on low-level failure. At the bottom we see the MWI was a
success. In the case that the diags show success but the lamp in fact is not on, then the
switch itself will need to be examined.
06/20/2007
12:34:48.807 |2557,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found display name (subscriber): Bailey Bell|
06/20/2007
12:34:48.807 |2557,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found device name: MWI-1|
06/20/2007
12:34:48.807 |2557,,,Notifier,12,Error getting value
of named property SubscriberObjectId for Bailey Bell.
HRESULT:80004005|
06/20/2007
12:34:48.807 |2557,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found display dtmf: 456|
06/20/2007
12:34:48.807 |2557,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found do report flag: true|
06/20/2007
12:34:48.807 |2557,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found voice count: 1|
06/20/2007
12:34:48.808 |2557,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found urgent count: 0|
06/20/2007
12:34:48.808 |2557,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found email count: 0|
06/20/2007
12:34:48.808 |2557,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found fax count: 0|
06/20/2007
12:34:48.808 |2557,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found initial delay: 0|
06/20/2007
12:34:48.808 |2557,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found result context: '(null)'|
06/20/2007
12:34:48.808 |2557,,,Notifier,12,CCsDeviceTask::LoadBasicInfoFromNamedProps
found switch objectid:
'e5a9d154-169a-48fa-87ff-5a1282b5f2c1'|
06/20/2007
12:34:48.808 |2557,,,Notifier,12,CCsMWIDevice::TransferPropertiesToTask
found mwi on/off type 2|
06/20/2007
12:34:48.808 |2557,,,Notifier,12,CCsMWIDevice::TransferPropertiesToTask
found mwi extension 2031|
06/20/2007
12:34:48.808 |2557,,,Notifier,12,CCsMWIDevice::TransferPropertiesToTask
found mwi port object id |
06/20/2007
12:34:48.808 |2557,,,Notifier,12,CCsMWIDevice::TransferPropertiesToTask
found mwi object id
b9ae93f1-0166-4509-aef8-39b69e75c1de|
06/20/2007
12:34:48.808 |2557,,,Notifier,12,CCsMWIDevice::TransferPropertiesToTask
found suspend update flag 0|
06/20/2007
12:34:48.808 |2557,,,Notifier,12,Queued MWI task for
mailuser=Bailey Bell, extension=2031, type=ON|
06/20/2007
12:34:48.828 |2557,,,Notifier,20,Ticket 10001 request
made for resource -1 (switch=0 caps=4) for Task Bailey Bell MWI-1 taskid 1|
06/20/2007
12:34:48.829 |2557,,,Notifier,20,Ticket 10001 pending
for requested resource -1|
06/20/2007
12:34:48.829 |2593,,,Notifier,20,Ticket 10001 found
for requested resource -1|
06/20/2007
12:34:48.830 |2593,,,Notifier,20,Ticket 10001 granted
for resource 1 (requested -1)|
06/20/2007
12:34:48.830 |2560,,,Notifier,12,MWI Device - MWI Entry CS_RESYNC_MWI_ON Received:
Mailuser Bailey Bell, Extension 2031, Port 1|
06/20/2007
12:34:48.832 |2560,CCM-1-002,,MiuSkinny,12,CAvSkinnyCallStatus::AdvanceCurrentState
- Old CallState=<Idle> New CallState=<Initiate
MWI>|
06/20/2007
12:34:48.832 |2560,CCM-1-002,,MiuSkinny,13,Send StationOffHookWithCgpnMessage (28 bytes) callingPartyNumber="2031"|
06/20/2007
12:34:48.832 |2560,CCM-1-002,,MiuSkinny,13,Send StationKeypadButtonMessage (8 bytes) kpButton=1=skpOne|
06/20/2007
12:34:48.832 |2560,CCM-1-002,,MiuSkinny,13,Send StationKeypadButtonMessage (8 bytes) kpButton=0=skpZero|
06/20/2007
12:34:48.832 |2560,CCM-1-002,,MiuSkinny,13,Send StationKeypadButtonMessage (8 bytes) kpButton=0=skpZero|
06/20/2007
12:34:48.832 |2560,CCM-1-002,,MiuSkinny,13,Send StationKeypadButtonMessage (8 bytes) kpButton=1=skpOne|
06/20/2007
12:34:48.833 |2560,CCM-1-002,,MiuSkinny,12,CAvSkinnyCallStatus::AdvanceCurrentState
- Old CallState=<Initiate MWI> New CallState=<Wait For MWI Response>|
06/20/2007
12:34:48.857 |2561,CCM-1-002,,MiuSkinny,12,Receive StationSetRingerMessage (20 bytes) ringMode=1=StationRingOff ringDuration=1=StationNormalRing lineInstance=0 callReference=0|
06/20/2007
12:34:48.857 |2561,CCM-1-002,,MiuSkinny,12,Ignore StationSetRingerMessage|
06/20/2007
12:34:48.861 |2557,CCM-1-002,,MiuSkinny,12,Receive StationSetSpeakerModeMessage (8 bytes) speakerMode=1=StationSpeakerOn|
06/20/2007
12:34:48.861 |2557,CCM-1-002,,MiuSkinny,12,Ignore StationSetSpeakerModeMessage|
06/20/2007
12:34:48.863 |2561,CCM-1-002,,MiuSkinny,12,Receive StationSetLampMessage (16 bytes) stimulus=9=SsLine stimulusInstance=1 lampMode=2=StationLampOn|
06/20/2007
12:34:48.863 |2561,CCM-1-002,,MiuSkinny,12,Processing StationSetLampMessage|
06/20/2007
12:34:48.865 |2557,CCM-1-002,,MiuSkinny,12,Receive StationCallStateMessage (28 bytes) callState=1=TsOffHook lineInstance=1 callReference=16792241 privacy=0 precedence=[precedenceLv=4 precedenceDm=0]|
06/20/2007
12:34:48.866 |2557,CCM-1-002,,MiuSkinny,12,Processing StationCallStateMessage|
06/20/2007
12:34:48.866 |2557,CCM-1-002,,MiuSkinny,12,CAvSkinnyCallStatus::SetCallReference
- Setting m_dwOriginalCall=16792241=0x01003ab1|
06/20/2007
12:34:48.867 |2561,CCM-1-002,,MiuSkinny,12,Receive StationSelectSoftKeysMessage (20 bytes) instance=1
reference=16792241 softKeySetIndex=4 validKeyMask=4294967295|
06/20/2007
12:34:48.867 |2561,CCM-1-002,,MiuSkinny,12,Ignore StationSelectSoftKeysMessage|
06/20/2007
12:34:48.867 |2561,CCM-1-002,,MiuSkinny,12,Receive StationDisplayPromptStatusMessage (48 bytes) timeOutValue=0 promptStatus="Enter
Number" lineInstance=1 callReference=16792241|
06/20/2007
12:34:48.867 |2561,CCM-1-002,,MiuSkinny,12,Ignore StationDisplayPromptStatusMessage|
06/20/2007
12:34:48.868 |2557,CCM-1-002,,MiuSkinny,12,Receive StationActivateCallPlaneMessage (8 bytes) lineInstance=1|
06/20/2007
12:34:48.868 |2557,CCM-1-002,,MiuSkinny,12,Ignore StationActivateCallPlaneMessage|
06/20/2007
12:34:48.868 |2557,CCM-1-002,,MiuSkinny,12,Receive StationStartToneMessage (20 bytes) tone=33=DtInsideDialTone lineInstance=1 callReference=16792241|
06/20/2007
12:34:48.868 |2557,CCM-1-002,,MiuSkinny,12,Processing StationStartToneMessage|
06/20/2007
12:34:48.901 |2561,CCM-1-002,,MiuSkinny,12,Receive StationStopToneMessage (12 bytes) lineInstance=1
callReference=16792241|
06/20/2007
12:34:48.901 |2561,CCM-1-002,,MiuSkinny,12,Processing StationStopToneMessage|
06/20/2007
12:34:48.904 |2557,CCM-1-002,,MiuSkinny,12,Receive StationSelectSoftKeysMessage (20 bytes) instance=1
reference=16792241 softKeySetIndex=6 validKeyMask=4294967295|
06/20/2007
12:34:48.904 |2557,CCM-1-002,,MiuSkinny,12,Ignore StationSelectSoftKeysMessage|
06/20/2007
12:34:48.913 |2561,CCM-1-002,,MiuSkinny,12,Receive StationSelectSoftKeysMessage (20 bytes) instance=1
reference=16792241 softKeySetIndex=8 validKeyMask=4294967295|
06/20/2007
12:34:48.913 |2561,CCM-1-002,,MiuSkinny,12,Ignore StationSelectSoftKeysMessage|
06/20/2007
12:34:48.913 |2561,CCM-1-002,,MiuSkinny,12,Receive StationDialedNumberMessage (36 bytes) dialedNumber="1001"
lineInstance=1 callReference=16792241|
06/20/2007
12:34:48.913 |2561,CCM-1-002,,MiuSkinny,12,Ignore StationDialedNumberMessage|
06/20/2007
12:34:48.913 |2561,CCM-1-002,,MiuSkinny,12,Receive StationCallStateMessage (28 bytes) callState=12=TsProceed lineInstance=1 callReference=16792241 privacy=0 precedence=[precedenceLv=4 precedenceDm=0]|
06/20/2007
12:34:48.913 |2561,CCM-1-002,,MiuSkinny,12,Processing StationCallStateMessage|
06/20/2007
12:34:48.913 |2561,CCM-1-002,,MiuSkinny,12,CAvSkinnyCallStatus::AdvanceCurrentState
- Old CallState=<Wait For MWI Response> New CallState=<MWI Success>|
06/20/2007
12:34:48.913 |2561,CCM-1-002,,MiuSkinny,12,Receive StationCallInfoMessage
(388 bytes) callingPartyName="Voicemail" callingParty="2031" calledPartyName=""
calledParty="1001" lineInstance=1
callReference=16792241 callType=2=TsOutBoundCall originalCalledPartyName=""
originalCalledParty="1001" lastRedirectingPartyName="" lastRedirectingParty="1001"
originalCdpnRedirectReason=0=RfrNoReason
lastRedirectingReason=0=RfrNoReason
cgpnVoiceMailbox="" cdpnVoiceMailbox=""
originalCdpnVoiceMailbox="" lastRedirectingVoiceMailbox="" callInstance=1 callSecurityStatus=0=CallSecurityStatusUnknown partyPIRestrictionBits=0|
06/20/2007
12:34:48.913 |2561,CCM-1-002,,MiuSkinny,12,Processing StationCallInfoMessage|
06/20/2007
12:34:48.913 |2561,CCM-1-002,,MiuSkinny,12,StationCallInfoMessage:
Extracted CallerID='2031' CalledID='1001'
RedirectReason=0=RfrNoReason
LastRedirectingID='1001' LastRedirectReason=0=RfrNoReason|
06/20/2007
12:34:48.914 |2561,CCM-1-002,,MiuSkinny,12,Receive StationStopToneMessage (12 bytes) lineInstance=1
callReference=16792241|
06/20/2007
12:34:48.914 |2561,CCM-1-002,,MiuSkinny,12,Processing StationStopToneMessage|
06/20/2007
12:34:48.914 |2561,CCM-1-002,,MiuSkinny,12,Receive StationSetLampMessage (16 bytes) stimulus=9=SsLine stimulusInstance=1 lampMode=1=StationLampOff|
06/20/2007
12:34:48.914 |2561,CCM-1-002,,MiuSkinny,12,Processing StationSetLampMessage|
06/20/2007
12:34:48.914 |2561,CCM-1-002,,MiuSkinny,12,Receive StationClearPromptStatusMessage (12 bytes) lineInstance=1 callReference=16792241|
06/20/2007
12:34:48.914 |2561,CCM-1-002,,MiuSkinny,12,Ignore StationClearPromptStatusMessage|
06/20/2007
12:34:48.914 |2561,CCM-1-002,,MiuSkinny,12,Receive StationCallStateMessage (28 bytes) callState=2=TsOnHook lineInstance=1 callReference=16792241 privacy=0 precedence=[precedenceLv=4 precedenceDm=0]|
06/20/2007
12:34:48.914 |2561,CCM-1-002,,MiuSkinny,12,Processing StationCallStateMessage|
06/20/2007
12:34:48.914 |2561,CCM-1-002,,MiuSkinny,12,CAvSkinnyCallStatus::AdvanceCurrentState
- Old CallState=<MWI Success> New CallState=<Idle>|
06/20/2007
12:34:48.914 |2561,CCM-1-002,,MiuSkinny,12,CAvSkinnyCallStatus::ClearCallReference
- Clearing m_dwOriginalCall=16792241=0x01003ab1|
06/20/2007
12:34:48.915 |2561,CCM-1-002,,MiuSkinny,12,Receive StationSelectSoftKeysMessage (20 bytes) instance=0
reference=0 softKeySetIndex=0 validKeyMask=4294967295|
06/20/2007
12:34:48.915 |2561,CCM-1-002,,MiuSkinny,12,Ignore StationSelectSoftKeysMessage|
06/20/2007
12:34:48.915 |2561,CCM-1-002,,MiuSkinny,12,Receive StationDefineTimeDate (40 bytes) timeDataInfo=[2007-06-20
12:35:21 wMilliseconds=0 wDayOfWeek=3]
systemTime=1182357321|
06/20/2007
12:34:48.915 |2561,CCM-1-002,,MiuSkinny,12,Ignore StationDefineTimeDate|
06/20/2007
12:34:48.915 |2561,CCM-1-002,,MiuSkinny,12,Receive StationSetSpeakerModeMessage (8 bytes) speakerMode=2=StationSpeakerOff|
06/20/2007
12:34:48.915 |2561,CCM-1-002,,MiuSkinny,12,Ignore StationSetSpeakerModeMessage|
06/20/2007
12:34:48.916 |2560,,,Notifier,12,Arbiter::SetMWI(2031
| ) returned [0x00000000; S_OK]|
06/20/2007
12:34:48.918 |2560,,,Notifier,12,Successfully completed MWI task
for mailuser=Bailey Bell, extension=2031, type=ON|
(Other Notificatino Problems Macro trace)
In this scenario the
Smart Host for the system is not set.
The CuNotifier
CuNotifier diag file
This diag file shows the new message event for Bailey Bell and
further down shows that the SMTP device is triggered by the new message and the
SMTP device schedule is on so a notification is started. The last line here shows that the notification
was successful. But we know it wasn’t so
we look at the CuCsMgr file below.
06/20/2007
14:01:00.696 |9050,,,Notifier,21,Read from NotifyQ:
NOTIFYQ_ACTION_MSG_NEW Bailey Bell MailboxObjectId=7ba4a3f2-84e7-425f-bee6-e5a981a0822a
Voice
06/20/2007
14:01:00.696 |9050,,,Notifier,21,Read from NotifyQ: + message seq#=37
message counts=0,2,0 seconds ago received=0|
06/20/2007
14:01:00.697 |9047,,,Notifier,21,MessageStoreMonitor
NOTIFYQ_ACTION_MSG_NEW Bailey Bell MailboxObjectId=7ba4a3f2-84e7-425f-bee6-e5a981a0822a
Voice Normal Normal-Priority 50019ad9-f360-4671-b3ad-a8e4fee06253|
06/20/2007
14:01:00.697 |9047,,,Notifier,21,MessageStoreMonitor +
message seq#=37 message counts=0,2,0 seconds ago
received=0|
06/20/2007
14:01:00.697 |9047,,,Notifier,21,Bailey Bell: NewMsgEvent
media=Voice msgType=
06/20/2007
14:01:00.697 |9047,,,Notifier,24,Adjust message counts by 1 for
media=Voice
priority=Normal-Priority msgType=Normal
starting 0,1,0,0,0,0,0,0,0|
06/20/2007
14:01:00.697 |9047,,,Notifier,24,Adjusted message counts for media=Voice priority=Normal-Priority msgType=Normal now 0,2,0,0,0,0,0,0,0|
06/20/2007
14:01:00.698 |9047,,,Notifier,25,Bailey Bell: evaluate
notification rules for message with media=Voice
msgType=
06/20/2007
14:01:00.698 |9047,,,Notifier,27,Schedule All Hours is currently ON Wednesday
time=14:1:0|
06/20/2007
14:01:00.698 |9047,,,Notifier,25,Bailey Bell: SMTP is triggered with new-voice-message
event.|
06/20/2007
14:01:00.698 |9047,,,Notifier,25,Bailey Bell: SMTP has criteria met with voice message
count greater than zero.|
06/20/2007
14:01:00.698 |9047,,,Notifier,25,Bailey Bell: SMTP does need outdial
request.|
06/20/2007
14:01:00.698 |9047,,,Notifier,25,Bailey Bell: starting notification for SMTP|
06/20/2007
14:01:00.851 |9048,,,Notifier,21,ResultMonitor
NOTIFYQ_ACTION_NOTIFICATION_SUCCESS Bailey Bell MailboxObjectId=7ba4a3f2-84e7-425f-bee6-e5a981a0822a
c05188e0-f967-4d9f-b6d0-7ee75c096e8c|
06/20/2007
14:01:00.851 |9048,,,Notifier,21,Bailey Bell: Handling notification success for device
SMTP rule objectid=c05188e0-f967-4d9f-b6d0-7ee75c096e8c|
CuCsMgr diag file
The CuCsMgr diag file shows the
notification for Bailey Bell’s SMTP device starting and shows it to be
successful. The error cannot be detected
here. So, let’s look at the SMTP diag file.
06/20/2007
14:01:00.782 |2560,,,Notifier,16,CCsDeviceTask::LoadBasicInfoFromNamedProps
found display name (subscriber): Bailey Bell|
06/20/2007
14:01:00.782 |2560,,,Notifier,16,CCsDeviceTask::LoadBasicInfoFromNamedProps
found device name: SMTP|
06/20/2007
14:01:00.782 |2560,,,Notifier,16,CCsDeviceTask::LoadBasicInfoFromNamedProps
found subscriber objectid: 99232b2e-6dd7-4f55-a3c6-935594318a08|
06/20/2007
14:01:00.782 |2560,,,Notifier,16,CCsDeviceTask::LoadBasicInfoFromNamedProps
found display dtmf: 456|
06/20/2007
14:01:00.782 |2560,,,Notifier,16,CCsDeviceTask::LoadBasicInfoFromNamedProps
found do report flag: true|
06/20/2007
14:01:00.782 |2560,,,Notifier,16,CCsDeviceTask::LoadBasicInfoFromNamedProps
found voice count: 2|
06/20/2007
14:01:00.782 |2560,,,Notifier,16,CCsDeviceTask::LoadBasicInfoFromNamedProps
found urgent count: 0|
06/20/2007
14:01:00.782 |2560,,,Notifier,16,CCsDeviceTask::LoadBasicInfoFromNamedProps
found email count: 0|
06/20/2007
14:01:00.782 |2560,,,Notifier,16,CCsDeviceTask::LoadBasicInfoFromNamedProps
found fax count: 0|
06/20/2007
14:01:00.782 |2560,,,Notifier,16,CCsDeviceTask::LoadBasicInfoFromNamedProps
found initial delay: 0|
06/20/2007
14:01:00.782 |2560,,,Notifier,16,CCsDeviceTask::LoadBasicInfoFromNamedProps
found result context: 'c05188e0-f967-4d9f-b6d0-7ee75c096e8c'|
06/20/2007
14:01:00.782 |2560,,,Notifier,16,CCsDeviceTask::LoadBasicInfoFromNamedProps
found switch objectid: ''|
06/20/2007
14:01:00.782 |2560,,,Notifier,16,CCsSMTPDevice::TransferPropertiesToTask
found urgent email count: 0|
06/20/2007
14:01:00.782 |2560,,,Notifier,16,CCsSMTPDevice::TransferPropertiesToTask
found Static Text: Work Messages|
06/20/2007
14:01:00.782 |2560,,,Notifier,16,CCsSMTPDevice::TransferPropertiesToTask
found SMTP address: 'jrygg@cisco.com'|
06/20/2007
14:01:00.782 |2560,,,Notifier,16,CCsSMTPDevice::TransferPropertiesToTask
found send count flag: true|
06/20/2007
14:01:00.782 |2560,,,Notifier,16,CCsSMTPDevice::TransferPropertiesToTask
found phone number (used as 'from' name): |
06/20/2007
14:01:00.782 |2560,,,Notifier,16,CCsSMTPDevice::TransferPropertiesToTask
found send callerid flag: true|
06/20/2007
14:01:00.783 |2560,,,Notifier,16,CCsSMTPDevice::TransferPropertiesToTask
found send pca link flag: false|
06/20/2007
14:01:00.815 |2560,,,Notifier,16,CuCredentialMgr::GetCredentials
failed; [0x80004005; E_FAIL]|
06/20/2007
14:01:00.831 |2560,,,Notifier,16,CDbCmd::ExecuteAdHoc(SELECT
s.DisplayName from vw_Subscriber
s, vw_DtmfAccessId d where s.ObjectId
= d.Parent_SubscriberObjectId and d.DtmfAccessId
= ?) returned an empty record set|
06/20/2007
14:01:00.842 |2560,,,Notifier,16,CDbCmd::ExecuteAdHoc(SELECT
s.DisplayName from vw_Subscriber
s, vw_DtmfAccessId d where s.ObjectId
= d.Parent_SubscriberObjectId and d.DtmfAccessId
= ?) returned an empty record set|
06/20/2007
14:01:00.842 |2560,,,Notifier,16,Caller ANI for SMTP
message=1. 2031
2.
2031
|
06/20/2007
14:01:00.842 |2560,,,Notifier,16,Queued SMTP task for
mailuser=Bailey Bell, SMTP, addr#=jrygg@cisco.com. Initial delay = 0 seconds|
06/20/2007
14:01:00.847 |2557,,,Notifier,16,The value of 'SMTPAaddress' is unityconnection@cuc-install-25.cisco.com|
06/20/2007
14:01:00.850 |2557,,,Notifier,16,Successfully completed SMTP
task for mailuser=Bailey Bell, SMTP, addr#=jrygg@cisco.com.|
SMTP Server diag file
No diagnostics are
turned on but this error case generates a log entry. The SMTP Smart Host is not setup. The message can be found in the SMTP server
bad mail folder. It should be deleted
from the bad mail folder as nothing can be done with it. Once the Smart Host is set up, the SMTP message
will be delivered.
06/20/2007
14:01:12.295 |9930,,,SMTP,11,Thread=SmtpClient-Delivery-4;
class=com.cisco.unity.smtp.client.CsUnitySmtpC_MsgDelivery;!!!
SMTP Smart Host Not set for the Server. Moving message to
bad mail folder. Message Id=MAL.74c109bd-6d66-46d4-b074-e332c5abaea1|
After setting SMTP
Smart Host, restarting the SMTP server and turning on all the SMTP micro
traces, the SMTP Server diag file shows the message
delivery.
The diagnostics show
the communication between SMTP servers.
Near the bottom we see that the message was delivered.
06/20/2007
14:27:09.550 |12353,,,SMTP,15,Thread=SmtpClient-cuc-install-25.cisco.com;
class=com.cisco.unity.smtp.client.CsUnitySmtpClient;Checking
SMTP Pickup Folder.|
06/20/2007
14:27:09.551 |12353,,,SMTP,15,Thread=SmtpClient-cuc-install-25.cisco.com;
class=com.cisco.unity.smtp.client.CsUnitySmtpClient;Pickup
Folder Monitor: Number of messages found =1|
06/20/2007
14:27:09.551 |12353,,,SMTP,15,Thread=SmtpClient-cuc-install-25.cisco.com;
class=com.cisco.unity.smtp.client.CsUnitySmtpC_MsgQueue;AddTask:
Number of messages in the Smtp Pickup Folder=1|
06/20/2007
14:27:09.551 |12355,,,SMTP,15,Thread=SmtpClient-Delivery-2;
class=com.cisco.unity.smtp.client.CsUnitySmtpC_MsgQueue;FetchTask: Number of
messages left in the Smtp Pickup Folder=0|
06/20/2007
14:27:09.551 |12355,,,SMTP,15,Thread=SmtpClient-Delivery-2;
class=com.cisco.unity.smtp.client.CsUnitySmtpC_MsgProcessingPool;Number of
message currently being SENT=1|
06/20/2007
14:27:09.551 |12355,,,SMTP,15,Thread=SmtpClient-Delivery-2;
class=com.cisco.unity.smtp.client.CsUnitySmtpC_MsgDelivery;Start: Processing
Message.
Path=/var/opt/cisco/connection/smtp/default/pickup/21e1701e-9b55-4464-b320-41b1c82bab6d.eml|
06/20/2007
14:27:09.553 |12355,,,SMTP,15,Thread=SmtpClient-Delivery-2;
class=com.cisco.unity.smtp.client.CsUnitySmtpConnector;SMTP
Server: 220 E2K-SEA-XCH2.sea-alpha.cisco.com Microsoft ESMTP MAIL Service,
Version: 5.0.2195.6713 ready at Wed, 20
Jun 2007 14:27:17 -0700 |
06/20/2007
14:27:09.554 |12355,,,SMTP,15,Thread=SmtpClient-Delivery-2;
class=com.cisco.unity.smtp.client.CsUnitySmtpConnector;Unity
SMTP Client: EHLO cuc-install-25.cisco.com|
06/20/2007
14:27:10.090 |12355,,,SMTP,15,Thread=SmtpClient-Delivery-2;
class=com.cisco.unity.smtp.client.CsUnitySmtpConnector;SMTP
Server: 250-E2K-SEA-XCH2.sea-alpha.cisco.com Hello [10.93.224.158]
250-TURN
250-ATRN
250-SIZE
250-ETRN
250-PIPELINING
250-DSN
250-ENHANCEDSTATUSCODES
250-8bitmime
250-BINARYMIME
250-CHUNKING
250-VRFY
250-X-EXPS
GSSAPI NTLM LOGIN
250-X-EXPS=LOGIN
250-AUTH
GSSAPI NTLM LOGIN
250-AUTH=LOGIN
250-X-LINK2STATE
250-XEXCH50
250
OK
|
06/20/2007
14:27:10.091 |12355,,,SMTP,15,Thread=SmtpClient-Delivery-2;
class=com.cisco.unity.smtp.client.CsUnitySmtpConnector;Unity
SMTP Client: MAIL FROM:<unityconnection@cuc-install-25.cisco.com>|
06/20/2007
14:27:10.285 |12355,,,SMTP,15,Thread=SmtpClient-Delivery-2;
class=com.cisco.unity.smtp.client.CsUnitySmtpConnector;SMTP
Server: 250 2.1.0 unityconnection@cuc-install-25.cisco.com....Sender OK|
06/20/2007
14:27:10.285 |12355,,,SMTP,15,Thread=SmtpClient-Delivery-2;
class=com.cisco.unity.smtp.client.CsUnitySmtpConnector;Unity
SMTP Client: RCPT TO:<jrygg@cisco.com>|
06/20/2007
14:27:10.509 |12355,,,SMTP,15,Thread=SmtpClient-Delivery-2;
class=com.cisco.unity.smtp.client.CsUnitySmtpConnector;SMTP
Server: 250 2.1.5 jrygg@cisco.com |
06/20/2007
14:27:10.509 |12355,,,SMTP,15,Thread=SmtpClient-Delivery-2;
class=com.cisco.unity.smtp.client.CsUnitySmtpConnector;Unity
SMTP Client: DATA|
06/20/2007
14:27:10.725 |12355,,,SMTP,15,Thread=SmtpClient-Delivery-2;
class=com.cisco.unity.smtp.client.CsUnitySmtpConnector;SMTP
Server: 354 Start mail input; end with <CRLF>.<CRLF>|
06/20/2007
14:27:11.005 |12355,,,SMTP,15,Thread=SmtpClient-Delivery-2;
class=com.cisco.unity.smtp.client.CsUnitySmtpConnector;SMTP
Server: 250 2.6.0
MAL.f4971715-58fc-465d-8f06-9abe85166024 Queued mail for delivery|
06/20/2007
14:27:11.005 |12355,,,SMTP,15,Thread=SmtpClient-Delivery-2;
class=com.cisco.unity.smtp.client.CsUnitySmtpConnector;Unity
SMTP Client: QUIT|
06/20/2007
14:27:11.159 |12355,,,SMTP,15,Thread=SmtpClient-Delivery-2;
class=com.cisco.unity.smtp.client.CsUnitySmtpConnector;SMTP
Server: 221 2.0.0 E2K-SEA-XCH2.sea-alpha.cisco.com Service closing transmission
channel|
06/20/2007
14:27:11.160 |12355,,,SMTP,15,Thread=SmtpClient-Delivery-2;
class=com.cisco.unity.smtp.client.CsUnitySmtpC_MsgDelivery;Host
Name=e2k-sea-xch2.cisco.com Message ID=MAL.f4971715-58fc-465d-8f06-9abe85166024
Message delivered to:jrygg@cisco.com|
06/20/2007
14:27:11.160 |12355,,,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/21e1701e-9b55-4464-b320-41b1c82bab6d.eml|
06/20/2007
14:27:11.160 |12355,,,SMTP,15,Thread=SmtpClient-Delivery-2;
class=com.cisco.unity.smtp.client.CsUnitySmtpC_MsgProcessingPool;Number of
message currently being SENT=0|
(Message Tracking macro traces)
MTA diag file
The lines in red shows
the message delivered to local recipient.
06/20/2007
14:38:23.146 |31245,,,MTA,14,Thread=mtaDropMailHandler; class=com.cisco.unity.mta.CsUnityMTA;Message
File transfered from MTA Drop Folder to MTA Queue for
delivery. File
Name=/var/opt/cisco/connection/spool/drop/5081f96e-1f7f-4e68-82f6-eefd4d90246e.eml|
06/20/2007
14:38:23.150 |31239,,,MTA,14,Thread=MtaMailDelivery-1;
class=com.cisco.unity.mta.CsUnityMTAOutgoingMessage;Message
File=/var/opt/cisco/connection/spool/UmssMtaQueue/5081f96e-1f7f-4e68-82f6-eefd4d90246e.eml
has Rfc822 MessageId=MAL.c16ff3bd-2c42-4a72-8b3f-80c39bd9d8eb
Sender=Dora Bell <dbell@cuc-install-25.cisco.com>|
06/20/2007
14:38:23.221 |31239,,,MTA,14,Thread=MtaMailDelivery-1;
class=com.cisco.unity.mta.CsUnityMTALocalDelivery;Message Link: Rfc MessageId=MAL.c16ff3bd-2c42-4a72-8b3f-80c39bd9d8eb
maps to sqlMessageId=dfdaf145-ff13-4c0b-8da6-6e0dbf0b7e52|
06/20/2007
14:38:23.348 |31239,,,MTA,14,Thread=MtaMailDelivery-1;
class=com.cisco.unity.mta.CsUnityMTALocalDelivery;Message Delivered to
Recipient. SMTP Addreess=bbell@cuc-install-25.cisco.com
mailbox Id=7ba4a3f2-84e7-425f-bee6-e5a981a0822a|
06/20/2007
14:38:23.348 |31239,,,MTA,14,Thread=MtaMailDelivery-1;
class=com.cisco.unity.mta.CsUnityMTA;Message
Delivered successfully!! File
Name=/var/opt/cisco/connection/spool/UmssMtaQueue/5081f96e-1f7f-4e68-82f6-eefd4d90246e.eml|
06/20/2007
14:38:23.348 |31239,,,MTA,14,Thread=MtaMailDelivery-1;
class=com.cisco.unity.mta.CsUnityMTA;Deleting Message
from MTA Queue. File
Name=/var/opt/cisco/connection/spool/UmssMtaQueue/5081f96e-1f7f-4e68-82f6-eefd4d90246e.eml|
CuCsMgr diag file
This diag file shows the message retrieval.
06/20/2007
14:39:02.292 |2572,CCM-1-001,893B513AE8054951B886B0C1A23D1E41,CsMalUmss,23,Set read flag for
message {dfdaf145-ff13-4c0b-8da6-6e0dbf0b7e52} in folder
{420be59e-b1aa-46b1-8e5f-a187fdac47df} to TRUE|
06/20/2007
14:39:02.333 |2572,CCM-1-001,893B513AE8054951B886B0C1A23D1E41,CsMalUmss,22,Set delete flag for
message {dfdaf145-ff13-4c0b-8da6-6e0dbf0b7e52} in folder
{420be59e-b1aa-46b1-8e5f-a187fdac47df} to TRUE|
In this case, the MTA
service was stopped, a message from Dora Bell to Bailey Bell was left, Dore
Bell was
MTA diag file
The lines in read show
the message delivery failure.
06/20/2007
15:19:07.907 |9390,,,MTA,12,Thread=MtaMailDelivery-1;
class=com.cisco.unity.mta.CsUnityMTADirectoryAccess;Subscriber not found in Unity
Directory. Email:dbell@cuc-install-25.cisco.com|
06/20/2007
15:19:07.907 |9390,,,MTA,12,Thread=MtaMailDelivery-1;
class=com.cisco.unity.mta.CsUnityMTAOutgoingMessage;Error
resolving sender in Unity Directory. Sender=Dora Bell
<dbell@cuc-install-25.cisco.com>,
FilePath=/var/opt/cisco/connection/spool/UmssMtaQueue/c04efbe5-9a2d-49da-83c1-c8a23a8eee6f.eml|
06/20/2007
15:19:07.908 |9390,,,MTA,12,Thread=MtaMailDelivery-1;
class=com.cisco.unity.mta.CsUnityMTA;Message could not be delivered due to (Sender could
not be resolved in the Directory). Moving message file to MTA
badmail folder. Delivery Status=104 File
Name=/var/opt/cisco/connection/spool/UmssMtaQueue/c04efbe5-9a2d-49da-83c1-c8a23a8eee6f.eml|