Guest

Cisco Unity

Unity: VPIM Quick Tracing Guide

Document ID: 70548

Updated: Jul 26, 2006

   Print

Introduction

This document provides guidelines for tracing Voice Profile for Internet Mail (VPIM) messages in a Cisco Unity environment. This document only serves as a guide, and does not cover all situations. In order to troubleshoot some issues, you might need to collect more data than what this document mentions.

Prerequisites

Requirements

Cisco recommends that you have knowledge of these topics:

  • Cisco Unity

  • Microsoft Exchange

Components Used

The information in this document is based on these software and hardware versions:

  • Cisco Unity

  • Microsoft Exchange

  • Avaya Interchange Private Branch Exchange (PBX)

The information in this document was created from the devices in a specific lab environment. All of the devices used in this document started with a cleared (default) configuration. If your network is live, make sure that you understand the potential impact of any command.

Conventions

Refer to Cisco Technical Tips Conventions for more information on document conventions.

Traces to Turn On

Microsoft Exchange Server

Complete these steps to turn on Microsoft Exchange server traces:

  1. Choose Start > Programs > Microsoft Exchange > System Manager in order to display the Exchange System Manager (Figure 1).

    Figure 1—Exchange System Manager

    vpim-quick-trace-1.gif

  2. Complete these steps in order to use the Message Tracking Center to examine outgoing and incoming messages (see arrow B in Figure 1):

    1. Expand First Organization > Servers in the left pane in Figure 1.

    2. Right-click on the server name and choose Properties (see arrow A in Figure 1). The Server Properties window is displayed (see Figure 2).

      Figure 2—Server Properties

      vpim-quick-trace-2.gif

    3. Select General (see arrow A in Figure 2).

    4. Check Enable subject logging and display (see arrow B in Figure 2).

    5. Check Enable message tracking (see arrow C in Figure 2).

    6. Check Remove log files (see arrow D in Figure 2).

    7. Enter 7 in the Remove files older than (days) field (see arrow E in Figure 2).

    8. Click Apply (see arrow F in Figure 2).

  3. Complete these steps in order to enable the logging of SMTP messages:

    1. Expand First Organization > Servers > [Server Name] > Protocols > SMTP in the left pane in Figure 1.

    2. Right-click Default SMTP Virtual Server (see arrow C in Figure 1) and choose Properties in order to display the Default SMTP Virtual Server Properties window (see Figure 3).

      Figure 3—Default SMTP Virtual Server Properties

      vpim-quick-trace-3.gif

    3. Check Enable logging (see arrow B in Figure 3).

    4. Choose NCSA Common Log File Format from the Active log format drop-down list (see arrow C in Figure 3).

    5. The SMTP messages are stored in this directory:

      C:\WINNT\system32\LogFiles\SMTPSVC1\
  4. Complete these steps in order to turn on the trace for the Voice Connector activity:

    1. Expand First Organization > Connectors in the left pane in Figure 1.

    2. Right-click Exchange 2000 Voice Connector and choose Properties in order to display the Voice Connector Properties window (see Figure 4).

      Figure 4—Voice Connector Properties

      vpim-quick-trace-4.gif

    3. Click the Advanced menu bar (see arrow A in Figure 4).

    4. Choose Information from the Logging Level drop-down list in the Logging section.

    5. Click OK (see arrow C in Figure 4).

    6. The Voice Connector service stores its logs in this directory (see arrow A in Figure 5):

      C:\Program Files\Exchsrvr\VoiceGateway/logfiles

      Valid log files are displayed as shown by arrow B in Figure 5.

      Figure 5—The Voice Connector Log Files

      vpim-quick-trace-5.gif

      Note: In order for the logging level change to take effect, you must stop and start the Voice Connector service. Either stop/start the Voice Connector service through Services or right-click the Voice Connector.

Registry Setting for the Unity Server

Two registry keys should be set. They are Avlvc and AvTransSink.

AvIvc

The registry path for Avlvc is:

HKEY_LOCAL_MACHINE\SOFTWARE\Active Voice\AvIvc

See arrow A in Figure 6.

Once you locate AvIvc, add a new string variable named StoreFiles (see arrow B in Figure 6). The assigned registry value represents a directory location (see arrow B in Figure 6). In this example the directory is C:\Temp\. Create this directory if it does not already exist.

Figure 6—Set the Registry Value of StoreFiles

vpim-quick-trace-6.gif

The c:\Temp\ (see arrow A in Figure 7) is the location to store the VPIM messages (see arrow B in Figure 7) created by the Voice Connector.

Figure 7

vpim-quick-trace-7.gif

AvTransSink

The registry path for AvTransSink is:

HKEY_LOCAL_MACHINE\SOFTWARE\Active Voice\AvTransSink

See arrow A in Figure 8.

Locate AvTransSink and set LogLevel to 1 (see arrow B in Figure 8).

Figure 8—Registry Key - AvTransSink

vpim-quick-trace-8.gif

VPIM Data Flow

Figure 9 displays the VPIM data flow through the network:

  1. Cisco Unity is called and a voice message is sent (see arrow A in Figure 9).

  2. Delivery location 91 is entered followed by the voicemail box of the recipient, 2166898211 (see arrow B in Figure 9).

  3. The message is delivered to IMCEAVPIM-91 (see arrow C in Figure 9). The From and To addresses are Dave, Test Phone and VPIM-91_2166898211.

    From: Dave, Test Phone
    To: VPIM-91_2166898211
  4. The VPIM message is processed and the From and To fields are modified (see arrow D in Figure 9). The new From and To addresses are 6203@unitybfs.com and 2166898211@keyhub.interchange.com.

  5. Message is transferred to keyhub.interchange.com (see arrow E in Figure 9).

    Note: The domain keyhub.interchange.com is the PBX domain on the other side of the network to which Cisco Unity was sending messages.

Figure 9—VPIM Data Flow

vpim-quick-trace-9.gif

Trace Message from Cisco Unity to Interchange

For this example, extension 6203 at the Cisco Unity site sends a voicemail to 912166898211. Extension 6203 is Cisco Unity user Dave, Test Phone. Now that all the traces are turned and a VPIM message is sent from Cisco Unity to the delivery location that represents Interchange, return to the Exchange System Manager.

Complete these steps in order to track messages on Exchange 2000:

  1. Open the Exchange System Manager.

  2. Double-click Tools and choose Message Tracking Center from the Console tree.

  3. Right-click in the right pane and choose Track Message.

  4. Select a server (see arrow A in Figure 10) and a date/time range for the Logged Between and and boxes (see arrow B in Figure 10).

    Note: Do not use the Sender box (see arrow C in Figure 10) because with VPIM messages, the From field changes after the message is processed by the Voice connector. You can follow the To/From field changes in this example:

    Figure 10—Message Tracking Center

    vpim-quick-trace-10.gif

  5. Double-click this line entry (see arrow C in Figure 10) to see a detailed routing of the message (see Figure 11).

    1/21/2006 10:56 AM  Dave, Test Phone
    Figure 11—Message History - Dave, Test Phone

    vpim-quick-trace-11.gif

    Notice how the message is addressed:

    From: Dave, Test Phone
     
    To: VPIM-91_2166898211

    It is sent from Dave to 2166898211. Also notice the fifth line (see arrow A in Figure 11):

    SMTP: Message Delivered Locally to IMCEAVOUN-91+5F2166898211@UnityBFS

    This line shows that the message is delivered to the Voice Connector.

Voice Connector Processing Outgoing VPIM Message

For a Voice Connector that processes an outgoing VPIM message, view the trace from the Voice Connector. The path that holds the log is:

c:Program Files > Exchsrvr > Voice Gateway > logFiles

This output shows one transaction with the ID of 10FC.

Note: This output is wrapped over several lines for spatial reasons, contains an extra space between entries, and points of interest are in bold.

02/21/06 10:56:22 10FC INFO (hr=0) Add into message Queue. 
Message ID=000000001A8179C02788944584F6F4D7A42585990100082738D155AEDF4981DA
04505A5DA4610000000891890000 =78FILE=e:\Views\cs_CU4.0.4.221\un_Doh3\
ExVoiceGateway2000\GwIvc\AvMessageQueue.cpp)
.
.
02/21/06 10:56:22 10FC INFO (hr=0) CAvVpimDelivery::SendOutVpimMessage:
 !!!!! Processing Outgoing VPIM Voice message !!!!!! 
(LINE=181 FILE=e:\Views\cs_CU4.0.4.221\un_Doh3\ExVoiceGateway2000\GwIvc\
VPimDelivery.cpp)
.
.
02/21/06 10:56:22 10FC INFO (hr=0) Get User Information for User: 
/O=UNITYBFS/OU=FIRST ADMINISTRATIVE GROUP/CN=RECIPIENTS/CN=TDAVE 
(LINE=53 FILE=e:\Views\cs_CU4.0.4.221\un_Doh3\ExVoiceGateway2000\GwIvc\
AvADUserHomedServer.cpp)
.
.
02/21/06 10:56:22 10FC INFO (hr=0) VPIM Sender(/O=UNITYBFS/OU=FIRST 
ADMINISTRATIVE GROUP/CN=RECIPIENTS/CN=TDAVE). 
Extension Found= 6203, UM Domain =unitybfs.com (
LINE=471 FILE=e:\Views\cs_CU4.0.4.221\un_Doh3\ExVoiceGateway2000\GwIvc\
AvVPimOutMessage.cpp)
.
.
02/21/06 10:56:22 10FC INFO (hr=0) Get Voice Name for User: 
/O=UNITYBFS/OU=FIRST ADMINISTRATIVE GROUP/CN=RECIPIENTS/CN=TDAVE 
(LINE=1741 FILE=e:\Views\cs_CU4.0.4.221\un_Doh3\ExVoiceGateway2000\GwIvc\
AvADUserHomedServer.cpp)
.
.
02/21/06 10:56:22 10FC INFO (hr=0) CAvVpimDelivery::
WriteSenderVoiceName: Codec Conversion to G726 required for voice name. 
(LINE=1018 FILE=e:\Views\cs_CU4.0.4.221\un_Doh3\ExVoiceGateway2000\GwIvc\
VPimDelivery.cpp)
.
.
02/21/06 10:56:22 10FC INFO (hr=0) Attachment PreProcessor. Attachment count=1 
(LINE=1390 FILE=e:\Views\cs_CU4.0.4.221\un_Doh3\ExVoiceGateway2000\GwIvc\VPimDelivery.cpp)
.
.
02/21/06 10:56:22 10FC INFO (hr=0) Attachment Post Processor. Attachment count=1 
(LINE=1473 FILE=e:\Views\cs_CU4.0.4.221\un_Doh3\ExVoiceGateway2000\GwIvc\VPimDelivery.cpp)
.
.
02/21/06 10:56:22 10FC INFO (hr=0) Current Message attachment will be converted 
to Codec : G726 (LINE=752 FILE=e:\Views\cs_CU4.0.4.221\un_Doh3\ExVoiceGateway2000\
GwIvc\VPimDelivery.cpp)
.
.
02/21/06 10:56:22 10FC INFO (hr=0) Delivered file to SMTP directory 
(D:\Program Files\Exchsrvr\Mailroot\vsi 1\pickup\VPM1F7.tmp) 
(LINE=367 FILE=e:\Views\cs_CU4.0.4.221\un_Doh3\ExVoiceGateway2000\GwIvc\
VPimDelivery.cpp)
.
.
02/21/06 10:56:22 10FC INFO (hr=0) Saved copy of Outgoing message at 
(C:\Temp\VPM1F7.tmp) (LINE=424 FILE=e:\Views\cs_CU4.0.4.221\un_Doh3\
ExVoiceGateway2000\GwIvc\VPimDelivery.cpp)
.
.
02/21/06 10:56:22 10FC INFO (hr=0) Remove from message Queue. Message 
ID=000000001A8179C02788944584F6F4D7A42585990100082738D155AEDF4981DA04505A5DA46
10000000891890000 (LINE=108 FILE=e:\Views\cs_CU4.0.4.221\un_Doh3\ExVoiceGateway2000\
GwIvc\AvMessageQueue.cpp)
.

This is the end of the 10FC transaction. Notice that a copy of the outgoing message is saved in the directory you defined earlier in the registry entry named StoreFiles.

Trace Message from Interchange to Unity

This section represents what Exchange does with a message after it returns from the Voice Connector.

Double-click this line entry (see arrow E in Figure 10) in order to see a detailed routing of the message (see Figure 12).

2/21/2006 10:56 AM  6203@unitybfs.com
Figure 12—Message History - 6203@unitybfs.com

vpim-quick-trace-12.gif

The message is forwarded to heyhub.interchange.com via the SMTP server. Logging is turned on via the Properties page for the SMTP server. The directory where the log is stored is:

C:\WINNT\system32\LogFiles\SMTPSVC1\

This output shows an outbound VPIM message that is sent by the SMTP service.

Note: This output is wrapped over several lines for spatial reasons, contains an extra space between entries, and the VPIM protocol is in bold.

10.195.133.180 - OutboundConnectionResponse [21/Feb/2006:10:56:22 -0500] 
"- -?220+keyhub.interchange.com+SMTP+service+ready SMTP" 0 45

10.195.133.180 - OutboundConnectionCommand [21/Feb/2006:10:56:22 -0500] 
"EHLO -?BFS18UNITYVM01S.UnityBFS.com SMTP" 0 4

10.195.133.180 - OutboundConnectionResponse [21/Feb/2006:10:56:22 -0500] 
"- -?250-keyhub.interchange.com+says+hello SMTP" 0 37

10.195.133.180 - OutboundConnectionCommand [21/Feb/2006:10:56:22 -0500] 
"MAIL -?FROM:<6203@unitybfs.com>+SIZE=43086 SMTP" 0 4

10.195.133.180 - OutboundConnectionResponse [21/Feb/2006:10:56:23 -0500] 
"- -?250+2.1.0+Originator+<6203@unitybfs.com>+ok SMTP" 0 43

10.195.133.180 - OutboundConnectionCommand [21/Feb/2006:10:56:23 -0500] 
"RCPT -?TO:<2166898211@keyhub.interchange.com> SMTP" 0 4

10.195.133.180 - OutboundConnectionResponse [21/Feb/2006:10:56:23 -0500] 
"- -?250+2.1.5+Recipient+<2166898211@keyhub.interchange.com>+ok SMTP" 0 58

10.195.133.180 - OutboundConnectionCommand [21/Feb/2006:10:56:23 -0500] 
"BDAT -?43086+LAST SMTP" 0 4

10.195.133.180 - OutboundConnectionResponse [21/Feb/2006:10:56:24 -0500] 
"- -?250+2.6.0+Message+accepted,+43086+octets+received SMTP" 0 49

10.195.133.180 - OutboundConnectionCommand [21/Feb/2006:10:56:24 -0500] 
"QUIT - SMTP" 0 4

10.195.133.180 - OutboundConnectionResponse [21/Feb/2006:10:56:24 -0500] "-

Interchange

This output is the log from Interchange. The VPIM commands from the Cisco Unity system are in bold.

02/21 10:52:22 vpims[50]: new Child [File ../Listener.cc Line 289]
02/21 10:52:22 vpims[51]: Socket Open to unitybfs.com 
[File ../SMTPserver.cc Line 115]
02/21 10:52:22 vpims[51]: RPLY>>220 keyhub.interchange.com 
SMTP service ready [File ../SMTP.cc Line 219]
02/21 10:52:22 vpims[51]: Vpim::Connect(). Function return. 
My process id = 15269 [File ../vpim.cc Line 758]
02/21 10:52:22 vpims[50]: Set VPIM port number (for activity.log) 
to 0 [File ../vpim.cc Line 2385]
02/21 10:52:22 vpims[51]: VPIM Server ::Reading Command [File ../vpim.cc Line 533]
02/21 10:52:22 vpims[51]: CMND<<EHLO BFS18UNITYVM01S.UnityBFS.com [File ../SMTP.cc Line 515]
02/21 10:52:22 vpims[51]: Opening ICHG database [File ../IC_Db.cc Line 169]
02/21 10:52:22 vpims[50]: Validating System:unitybfs.com 250 [File ../vpim.cc Line 260]
02/21 10:52:22 vpims[51]: RPLY>>250-keyhub.interchange.com says hello
250-BINARYMIME
250-CHUNKING
250-DSN
250-ENHANCEDSTATUSCODES
250-SIZE 60000000
250 VRFY [File ../SMTP.cc Line 219]
02/21 10:52:22 vpims[51]: VPIM Server ::Reading Command [File ../vpim.cc Line 533]
02/21 10:52:22 vpims[51]: CMND<<MAIL FROM:<6203@unitybfs.com> SIZE=43086 
[File ../SMTP.cc Line 515]
02/21 10:52:22 vpims[51]: node name for domain unitybfs.com is bfs18unityvm01s 
[File ../IC_Directory.cc Line 186]
02/21 10:52:22 vpims[51]: sender = 6203  nodeName.data = bfs18unityvm01s  
[File../IC_MsgAccess.cc Line 84]
02/21 10:52:22 vpims[51]: Sender valid: 6203@unitybfs.com [File ../vpim.cc Line429]
02/21 10:52:22 vpims[51]: RPLY>>250 2.1.0 Originator <6203@unitybfs.com> ok 
[File ../SMTP.cc Line 219]
02/21 10:52:22 vpims[51]: VPIM Server ::Reading Command [File ../vpim.cc Line 533]
02/21 10:52:22 vpims[51]: CMND<<RCPT TO:<2166898211@keyhub.interchange.com> 
[File ../SMTP.cc Line 515]
02/21 10:52:22 vpims[51]: RPLY>>250 2.1.5 Recipient <2166898211@keyhub.interchange.com> 
ok [File ../SMTP.cc Line 219]
02/21 10:52:22 vpims[51]: VPIM Server ::Reading Command [File ../vpim.cc Line 533]
02/21 10:52:22 vpims[51]: CMND<<BDAT 43086 LAST [File ../SMTP.cc Line 515]
02/21 10:52:22 vpims[51]: Create_Msg [File ../msg_store_client.cc Line 1616]
02/21 10:52:22 vpims[51]: ---------------[ New Body Part ]-------------------- 
[File ../mimeBodyPart.cc Line 129]
02/21 10:52:22 vpims[51]: Received time = Tue Feb 21 11:52:22 2006 
[File ../vpim.cc Line 1477]
02/21 10:52:23 vpims[51]:  The subject exclusion file contains 1 lines 
[File ../vpim.cc Line 3365]
02/21 10:52:23 vpims[51]: Putting subject Message from 6203 into msg store 
[File ../vpim.cc Line 1939]
02/21 10:52:23 icdb_put_msg_annotation[40]: Entered, msgh=0x8368df8, 
annotation=Message from 6203
02/21 10:52:23 vpims[51]: rcpt_mbox()=2166898211@keyhub.interchange.com 
[File ../xlator.cc Line 452]
02/21 10:52:23 vpims[51]: --------------------------[ New 822Message ]-------------- 
[File ../mimeMessageRFC822.cc Line 161]
02/21 10:52:23 vpims[51]: ----------[ 822 Headers ]---------- 
[File ../mimeMessageRFC822.cc Line 169]
02/21 10:52:23 vpims[51]: -----------------[ New 822Section ]-------------------- 
[File ../mimeMessageRFC822.cc Line 104]
02/21 10:52:23 vpims[51]: ----------[ Content Descriptor ]--------++ 
[File ../mimeContentDescriptor.cc Line 441]
02/21 10:52:23 vpims[51]:  [File ../mimeContentDescriptor.cc Line 447]
02/21 10:52:23 vpims[51]: Content-Type: multipart/Voice-Message; 
boundary="==AvVoice==98ba08bd-9cda-45bb-8c72-35c32f58cfe0"
 [File ../mimeContentDescriptor.cc Line 452]
02/21 10:52:23 vpims[51]: ----------[ Content Descriptor ]--------++ 
[File ../mimeContentDescriptor.cc Line 458]
02/21 10:52:23 vpims[51]: Processing Content-Type = Multipart/Voice-Message 
[File ../mimeSection.cc Line 229]
02/21 10:52:23 vpims[51]: ---------------[ New Body Part ]-------------------- 
[File ../mimeBodyPart.cc Line 129]
02/21 10:52:23 vpims[51]: -----------------[ New Multipart Section ]----------------- 
[File ../MimeMultipart.cc Line 157]
02/21 10:52:23 vpims[51]: ----------[ Content Descriptor ]---------- 
[File ../mimeContentDescriptor.cc Line 198]
02/21 10:52:23 vpims[51]: Content-Disposition: inline; voice=Originator-Spoken-Name 
[File ../mimeContentDescriptor.cc Line 203]
02/21 10:52:23 vpims[51]: Content-Type: Audio/32KADPCM 
[File ../mimeContentDescriptor.cc Line 208]
02/21 10:52:23 vpims[51]: ----------[ Content Descriptor ]---------- 
[File ../mimeContentDescriptor.cc Line 214]
02/21 10:52:23 vpims[51]: Processing Content-Type = Audio/32KADPCM 
[File ../mimeSection.cc Line 143]
02/21 10:52:23 vpims[51]: ---------------[ End Body Part ]-------------------- 
[File ../MimeMultipart.cc Line 166]
02/21 10:52:23 vpims[51]: -----------------[ End Multipart Section ]----------------- 
[File ../MimeMultipart.cc Line 168]
02/21 10:52:23 vpims[51]: -----------------[ New Multipart Section ]---------------------- 
[File ../MimeMultipart.cc Line 191]
02/21 10:52:23 vpims[51]: ----------[ Content Descriptor ]---------- 
[File ../mimeContentDescriptor.cc Line 198]
02/21 10:52:23 vpims[51]: Content-Disposition: inline; voice=Voice-Message 
[File ../mimeContentDescriptor.cc Line 203]
02/21 10:52:23 vpims[51]: Content-Type: Audio/32KADPCM 
[File ../mimeContentDescriptor.cc Line 208]
02/21 10:52:23 vpims[51]: ----------[ Content Descriptor ]---------- 
[File ../mimeContentDescriptor.cc Line 214]
02/21 10:52:23 vpims[51]: Processing Content-Type = Audio/32KADPCM 
[File ../mimeSection.cc Line 143]
02/21 10:52:23 vpims[51]: ---------------[ End Body Part ]-------------------- 
[File ../MimeMultipart.cc Line 166]
02/21 10:52:23 vpims[51]: -----------------[ End Multipart Section ]----------------- 
[File ../MimeMultipart.cc Line 168]
02/21 10:52:23 vpims[51]: -----------------[ End Multipart Body ]---------------------- 
[File ../MimeMultipart.cc Line 184]
02/21 10:52:23 vpims[51]: End of Message Found [File ../vpim.cc Line 2006]
02/21 10:52:23 vpims[51]: voiced name for 6173856203 was queued for register or update 
[File ../IC_MsgStore.cc Line 896]
02/21 10:52:23 vpims[50]: Done with UpdateVoicedName()  [File ../vpim.cc Line 2254]
02/21 10:52:24 vpims[51]: RPLY>>250 2.6.0 Message accepted, 43086 octets received 
[File ../SMTP.cc Line 219]
02/21 10:52:24 vpims[51]: VPIM Server ::Reading Command [File ../vpim.cc Line 533]
02/21 10:52:24 vpims[51]: CMND<<QUIT [File ../SMTP.cc Line 515]
02/21 10:52:24 vpims[51]: RPLY>>221 2.2.0 keyhub.interchange.com SMTP service closing 
[File ../SMTP.cc Line 219]
02/21 10:52:24 vpims[51]: Closing ICHG database [File ../IC_Db.cc Line 231]
02/21 10:52:24 vpims[51]: database closed [File ../IC_Db.cc Line 241]
02/21 10:52:24 vpims[50]: Child is exiting [File ../xlator.cc Line 948]

Related Information

Updated: Jul 26, 2006
Document ID: 70548