Cisco Support Community
cancel
Showing results for 
Search instead for 
Did you mean: 

Message Waiting Indicator (MWI) Traces

 

 

Introduction

 

 

Message Waiting Indicator (MWI) traces can be broken down into the following  categories

 

  • JTAPI Traces (used for Cisco Unified Communications Manager integrations)
  • SIP Methods  
    • Outcall
    • Subscribe-Notify
    • Unsolicited Notify

To start, always check to see what license is installed on the CUE module  (show software license):

 

 cue> show software licenses
Installed license files:
  - voicemail_lic.sig : 100 MAILBOX LICENSE

Core:
  - Application mode: CCM

The application mode (either CCM or CCME--for CallManager Express/Cisco  Unified CallManager Express), is crucial. With a CCME license, MWI will not work  when using Cisco Unified Communications Manager deployments.

 

With CCME deployments, the SIP MWI method (Outcall by default) can be  obtained with the show ccn subsystem sip command:

 

 br2213-cue> show ccn subsystem sip
SIP Gateway:                            14.87.32.1
SIP Port Number:                        5060
DTMF Relay:                             sip-notify,sub-notify
MWI Notification:                       outcall
Transfer Mode:                          semi attended(REFER)
SIP RFC Compliance:                     RFC3261

Additionally, the IP address and port must match the CCME, otherwise the MWI  will not arrive at the proper destination.

Now we can examine what the traces look like for each type of MWI method.

 

 

SIP Outcall Method

 

The default SIP MWI method is outcall. Until CUE version 2.3, it was the only  supported MWI option. It does not with CUCM integrations in SRST mode.

This method is fairly easy to understand. Every time a message is left or  retrieved, a call is placed to a number that CCME interprets as an MWI on or off  for part of the called number. For example, the MWI on extension may be  configured as "8000...." and the mailbox in CUE may be configured as extension  "1234". Therefore a call must be placed to "80001234" when a message is left  (and 80011234 when a message read). CCME's logic knows to take those first few  digits that match exactly and strip them off (i.e. 8000). The resulting  extension, "1234" need to match an ephone-dn.

 

The important part of the CME configuration is:

 

 ephone-dn  199
  number 8000........ secondary 8001........ no-reg both
  mwi on-off

!

The numbers configured are arbitrary but they must match what is configured  on the CUE and the number of dots following the number must match the number of  digits in the CME extensions. You cannot have variable length extensions in CUE  and have MWI notification work.

 

Aside from the CCME license and outcall MWI method, it must contain something  such as the following:

 

 ccn application ciscomwiapplication aa
  description "ciscomwiapplication"
  enabled
  maxsessions 6
  script "setmwi.aef"
  parameter "CallControlGroupID" "0"
  parameter "strMWI_OFF_DN" "8001"
  parameter "strMWI_ON_DN" "8000"
  end application

This output was obtained from the show run from CUE. The 'ccn  application' portion may be slightly different in older versions, but it always  references setmwi.aef. The 8000 / 8001 numbers mirror the CME config.  Note that there is no mention of the number of digits in the extension.

 

There are two ways to troubleshoot this. From the CUE traces, or from the CME  router itself. In the following example, we'll just look at the 'debug ccsip  messages' debug from the IOS router, not CUE. The CUE would contain essentially  the same messages (as it pertains to SIP signaling), but the direction would be  opposite (i.e. the INVITE message sent from CUE would appear as "Sent" by CUE  while in the example it is "Received" by the CME).

 

 Sep 22 11:12:04.249: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
INVITE sip:800082213128@14.87.32.1:5060;user=phone SIP/2.0
Via: SIP/2.0/UDP 14.87.32.4:5060;branch=z9hG4bKuGWurmFiRM2U+PTXasRl2Q~~11884
Max-Forwards: 70
To: <sip:800082213128@14.87.32.1:5060;user=phone>
From: <sip:82213001@14.87.32.4:5060>;tag=cue6d9c9249
Call-ID: 12220963242343@14.87.32.4
CSeq: 1 INVITE
Content-Length: 174
Contact: <sip:82213001@14.87.32.4:5060>
Content-Type: application/sdp
Cisco-Gcid: 8A9E068A-011C-1000-4000-001125CUCE68
Call-Info: <sip:14.87.32.4:5060>;method="NOTIFY;Event=telephone-event;Duration=2000"
Allow-Events: telephone-event

v=0
o=CiscoSystemsSIP-Workflow-App-UserAgent 1678 1678 IN IP4 14.87.32.4
s=SIP Call
c=IN IP4 14.87.32.4
t=0 0
m=audio 16898 RTP/AVP 0
a=rtpmap:0 pcmu/8000
a=ptime:20

Sep 22 11:12:04.257: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 14.87.32.4:5060;branch=z9hG4bKuGWurmFiRM2U+PTXasRl2Q~~11884
From: <sip:82213001@14.87.32.4:5060>;tag=cue6d9c9249
To: <sip:800082213128@14.87.32.1:5060;user=phone>
Date: Mon, 22 Sep 2008 15:12:04 GMT
Call-ID: 12220963242343@14.87.32.4
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 1 INVITE
Allow-Events: telephone-event
Content-Length: 0



Sep 22 11:12:04.269: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 14.87.32.4:5060;branch=z9hG4bKuGWurmFiRM2U+PTXasRl2Q~~11884
From: <sip:82213001@14.87.32.4:5060>;tag=cue6d9c9249
To: <sip:800082213128@14.87.32.1:5060;user=phone>;tag=88B031B8-8C8
Date: Mon, 22 Sep 2008 15:12:04 GMT
Call-ID: 12220963242343@14.87.32.4
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 1 INVITE
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
Allow-Events: telephone-event
Contact: <sip:800082213128@14.87.32.3:5060>
Content-Length: 0


Sep 22 11:12:09.241: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
CANCEL sip:800082213128@14.87.32.1:5060;user=phone SIP/2.0
Via: SIP/2.0/UDP 14.87.32.4:5060;branch=z9hG4bKuGWurmFiRM2U+PTXasRl2Q~~11884
Max-Forwards: 70
To: <sip:800082213128@14.87.32.1:5060;user=phone>
From: <sip:82213001@14.87.32.4:5060>;tag=cue6d9c9249
Call-ID: 12220963242343@14.87.32.4
CSeq: 1 CANCEL
Content-Length: 0

 
Sep 22 11:12:09.245: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 14.87.32.4:5060;branch=z9hG4bKuGWurmFiRM2U+PTXasRl2Q~~11884
From: <sip:82213001@14.87.32.4:5060>;tag=cue6d9c9249
To: <sip:800082213128@14.87.32.1:5060;user=phone>
Date: Mon, 22 Sep 2008 15:12:09 GMT
Call-ID: 12220963242343@14.87.32.4
CSeq: 1 CANCEL
Content-Length: 0

 
Sep 22 11:12:09.249: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
BYE sip:800082213128@14.87.32.3:5060 SIP/2.0
Via: SIP/2.0/UDP 14.87.32.4:5060;branch=z9hG4bKuGWurmFiRM2U+PTXasRl2Q~~11885
Max-Forwards: 70
To: <sip:800082213128@14.87.32.1:5060;user=phone>;tag=88B031B8-8C8
From: <sip:82213001@14.87.32.4:5060>;tag=cue6d9c9249
Call-ID: 12220963242343@14.87.32.4
CSeq: 2 BYE
Content-Length: 0
Contact: <sip:82213001@14.87.32.4:5060>

 
Sep 22 11:12:09.249: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 14.87.32.4:5060;branch=z9hG4bKuGWurmFiRM2U+PTXasRl2Q~~11885
From: <sip:82213001@14.87.32.4:5060>;tag=cue6d9c9249
To: <sip:800082213128@14.87.32.1:5060;user=phone>;tag=88B031B8-8C8
Date: Mon, 22 Sep 2008 15:12:09 GMT
Call-ID: 12220963242343@14.87.32.4
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 2 BYE
Content-Length: 0

The CUE module, simply looks for the Ringing message. Once this has been  received (i.e. sent by CME), then it can disconnect the call. Issues tend to  crop up when CME is translating the numbers sent by CUE. Another issue may occur  if there are other dial-peers that match besides the MWI on/off numbers. Then  the call is either routed to the wrong destination, or the call is set up  incorrectly. For example, if the CME is configured with something other than  G.711, then CME may respond to the CUE's INVITE with

 

 SIP/2.0 488 Not Acceptable Media

To resolve this, carefully look at the CME dial-plan. Other debugs may be  required. The important thing to look at here is that the call arrived at the  correct CME and that it is sending a Ringing back.

 

 

SIP Subscribe Notify

 

The Subscribe Notify SIP MWI method in most cases is the preferred MWI  method. Each ephone-dn that is configured subscribes to the CUE for MWI  notifications. It works with regular CCME as well as with CUCM deployments with  SRST fallback.

 

The CME configuration requires:

 sip-ua
  mwi-server ipv4:14.87.32.4 expires 3600 port 5060 transport udp

 

The IP address (as well as the port, of which 5060 is the default) must match  that of the CUE module. In earlier IOS releases (prior to 12.3(11)T7), this  configuration was done under the telephony-service subsection, instead of  under sip-ua.

 

For SRST mode, the additional configuration is required:

 

 call-manager-fallback
  mwi relay

For CCME deployments, each ephone-dn must also be configured with the mwi sip  statement to subscribe the directory number. Example:

 

 ephone-dn 10
  mwi sip

 

 Sep 22 13:40:02.027: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SUBSCRIBE sip:82213128@14.87.32.4:5060 SIP/2.0
Via: SIP/2.0/UDP 14.87.32.3:5060;branch=z9hG4bK940F25D3
From: <sip:82213128@14.87.32.3>;tag=8937A600-196
To: <sip:82213128@14.87.32.4>
Call-ID: 513E7282-880411DD-9412F24F-455EF452@14.87.32.3
CSeq: 101 SUBSCRIBE
Max-Forwards: 70
Date: Mon, 22 Sep 2008 17:40:01 GMT
User-Agent: Cisco-SIPGateway/IOS-12.x
Event: message-summary
Expires: 3600
Contact: <sip:82213128@14.87.32.3:5060>
Accept: application/simple-message-summary
Content-Length: 0
 
Sep 22 13:40:02.227: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 202 Accepted
Via: SIP/2.0/UDP 14.87.32.3:5060;branch=z9hG4bK940F25D3
To: <sip:82213128@14.87.32.4>;tag=e271a0c2-12983
From: <sip:82213128@14.87.32.3>;tag=8937A600-196
Call-ID: 513E7282-880411DD-9412F24F-455EF452@14.87.32.3
CSeq: 101 SUBSCRIBE
Content-Length: 0
Expires: 3600
Contact: sip:82213128@14.87.32.4
Allow-Events: refer
Allow-Events: telephone-event
Allow-Events: message-summary
  
Sep 22 13:40:02.339: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
NOTIFY sip:82213128@14.87.32.3:5060 SIP/2.0
Via: SIP/2.0/UDP 14.87.32.4:5060;branch=z9hG4bKuGWurmFiRM2U+PTXasRl2Q~~11895
Max-Forwards: 70
To: <sip:82213128@14.87.32.3>;tag=8937A600-196
From: <sip:82213128@14.87.32.4>;tag=e271a0c2-12983
Call-ID: 513E7282-880411DD-9412F24F-455EF452@14.87.32.3
CSeq: 1 NOTIFY
Content-Length: 22
Contact: sip:82213128@14.87.32.4
Event: message-summary
Allow-Events: refer
Allow-Events: telephone-event
Allow-Events: message-summary
Subscription-State: active
Content-Type: application/simple-message-summary

Messages-Waiting: yes

Sep 22 13:40:02.339: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 14.87.32.4:5060;branch=z9hG4bKuGWurmFiRM2U+PTXasRl2Q~~11895
From: <sip:82213128@14.87.32.4>;tag=e271a0c2-12983
To: <sip:82213128@14.87.32.3>;tag=8937A600-196
Date: Mon, 22 Sep 2008 17:40:02 GMT
Call-ID: 513E7282-880411DD-9412F24F-455EF452@14.87.32.3
CSeq: 1 NOTIFY
Content-Length: 0

We see that the subscription itself is a SUBSCRIBE message followed by an  Accepted message from CUE. In this case, the MWI state is on. CUE sends the  NOTIFY and CME acknowledges it with an OK. If the user calls in and reads all  their messages, the MWI will be turned off with a message such as the following  from the debug ccsip messages output of the CME router.

 

 Sep 22 14:08:58.025: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
NOTIFY sip:82213128@14.87.32.3:5060 SIP/2.0
Via: SIP/2.0/UDP 14.87.32.4:5060;branch=z9hG4bKuGWurmFiRM2U+PTXasRl2Q~~11897
Max-Forwards: 70
To: <sip:82213128@14.87.32.3>;tag=8937A600-196
From: <sip:82213128@14.87.32.4>;tag=e271a0c2-12983
Call-ID: 513E7282-880411DD-9412F24F-455EF452@14.87.32.3
CSeq: 3 NOTIFY
Content-Length: 21
Contact: sip:82213128@14.87.32.4
Event: message-summary
Allow-Events: refer
Allow-Events: telephone-event
Allow-Events: message-summary
Subscription-State: active
Content-Type: application/simple-message-summary

Messages-Waiting: no

Sep 22 14:08:58.025: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 14.87.32.4:5060;branch=z9hG4bKuGWurmFiRM2U+PTXasRl2Q~~11897
From: <sip:82213128@14.87.32.4>;tag=e271a0c2-12983
To: <sip:82213128@14.87.32.3>;tag=8937A600-196
Date: Mon, 22 Sep 2008 18:08:58 GMT
Call-ID: 513E7282-880411DD-9412F24F-455EF452@14.87.32.3
CSeq: 3 NOTIFY
Content-Length: 0

From the CUE point-of-view, the subscribed directory numbers can be viewed  with the show ccn sip subscription mwi command:

 

 cue> show ccn sip subscription mwi 
 DN                       Subscription Time                Expires 
-------------------------------------------------------------------

82213128        Mon Sep 22 13:40:02 EDT 2008                  3600          
82213124        Mon Sep 22 13:35:23 EDT 2008                  3600          
...

 

SIP Unsolicited Notify

 

Unsolicited SIP notifies do not require any subscription, CUE simply sends a  Notify message to CME whenever the voicemail mailbox has a new message. The MWI  method is also compatible with SRST mode (requires mwi relay configuration under call-manager-fallback). In the CCME configuration we  have

:

 sip-ua 
  mwi-server ipv4:14.87.32.4 expires 3600 port 5060 transport udp unsolicited

 

The IP address is that of the CUE, of course. In older IOS versions, this  configuration would take place in the telephony-service section. The mwi  sip command must also be entered under each ephone-dn for which the MWI  should used.

 

The following traces are taken from the debug ccsip messages output of  the CME router.

 

 Sep 22 14:47:37.566: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
NOTIFY sip:82213128@14.87.32.1:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 14.87.32.4:5060;branch=z9hG4bKuGWurmFiRM2U+PTXasRl2Q~~11900
Max-Forwards: 70
To: <sip:82213128@14.87.32.1:5060>
From: <sip:82213128@14.87.32.4:5060>;tag=ds5320ebc7
Call-ID: ae3401d0-12984@sip:82213128@14.87.32.4:5060
CSeq: 1 NOTIFY
Content-Length: 22
Contact: sip:82213128@14.87.32.4:5060
Content-Type: application/simple-message-summary
Event: message-summary

Messages-Waiting: yes


Sep 22 14:47:37.570: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 14.87.32.4:5060;branch=z9hG4bKuGWurmFiRM2U+PTXasRl2Q~~11900
From: <sip:82213128@14.87.32.4:5060>;tag=ds5320ebc7
To: <sip:82213128@14.87.32.1:5060>;tag=897589AC-1807
Date: Mon, 22 Sep 2008 18:47:37 GMT
Call-ID: ae3401d0-12984@sip:82213128@14.87.32.4:5060
CSeq: 1 NOTIFY
Content-Length: 0

 

MWI with Cisco Unified Communications Manager  (CUCM)

 

When the CUE is registered with a CallManager system, it uses the JTAPI  protocol to generate the MWI notification. While this is not a full call, it  still utilizes some of the Calling Search Space configuration. In newer CUE  versions, a dedicated "port" for MWI can be configured.

From the CUE's perspective, to see the signaling between the CUE and  CallManager, additional JTAPI traces must be enabled (ccn trace  jtapi...). After enabling the traces, the CUE module has be reloaded for the  file to be written. In this example we see an MWI request from CUE for mailbox  82011100 and CallManager's response (0). LampMode 2 is an MWI on event. Note  that the JTAPI traces are very verbose. The traces here are simply to illustrate  the communication. The traces should be disabled for normal CUE operation.

 

 1529: Sep 22 15:11:03.393 EDT %JTAPI-JTAPI-7-UNK:(P1-br2011cue)[Thread-91][82011080:All_Phones_PT]Request: setMessageWaiting ( 82011100,true )
1530: Sep 22 15:11:03.394 EDT %JTAPI-PROTOCOL-7-UNK:(P1-14.86.11.10) [Thread-91] sending: com.cisco.cti.protocol.LineSetMessageWaitingRequest {
   sequenceNumber    = 170
   lineCallManagerID = 5
   lineID            = 54
   lineName          = 82011100
   lampMode          = 2
   }
1531: Sep 22 15:11:03.409 EDT %JTAPI-PROTOCOL-7-UNK:(P1-14.86.11.10) received Response: com.cisco.cti.protocol.LineSetMessageWaitingResponse {
   sequenceNumber    = 170
   result            = 0
   lineCallManagerID = 5
   lineID            = 54
   }

 

The following a an MWI off event, where the LampMode is 1.

 2003: Sep 22 15:19:23.069 EDT %JTAPI-JTAPI-7-UNK:(P1-br2011cue)[Thread-90][82011080:All_Phones_PT]Request: setMessageWaiting ( 82011100,false )
2004: Sep 22 15:19:23.070 EDT %JTAPI-PROTOCOL-7-UNK:(P1-14.86.11.10) [Thread-90] sending: com.cisco.cti.protocol.LineSetMessageWaitingRequest {
   sequenceNumber    = 175
   lineCallManagerID = 5
   lineID            = 54
   lineName          = 82011100
   lampMode          = 1
   }
2005: Sep 22 15:19:23.084 EDT %JTAPI-PROTOCOL-7-UNK:(P1-14.86.11.10) received Response: com.cisco.cti.protocol.LineSetMessageWaitingResponse {
   sequenceNumber    = 175
   result            = 0
   lineCallManagerID = 5
   lineID            = 54
   }

 

It is important to remember that CUE does NOT use the CUCM's MWI on/off  numbers at all. It does rely on the Calling Search spaces of the configured MWI  port (if configured), or that of the CTI ports. The Calling Search space must be  able to reach the extension for which the MWI is being set to. I.e. if we're  trying to set the lamp for extension 1234, then the Calling Search Space  assigned to either the MWI port (if configured) or the CTI ports must be able to  dial 1234.

 

Generic CUE Traces for MWI

 

The CUE traces can generate quite a bit of tracing, especially since it's  difficult to isolate just the MWI-related potions of the trace. In this example,  we have a CUE that is integrated to CCUM and the message is checked via IMAP, so  there's no additional call.

 

The entire trace (including the default trace levels for CUE 3.2.1) follows.  Note that the MWI portion simply triggers the setMWI script. The rest is  basically custom script troubleshooting. This won't be necessary for all but the  most catastrophic problems. In real life, focus should be placed on the  signaling, i.e. the CME<->CUE SIP signaling or CUE<->CCM via JTAPI.

 

 5005 09/22 15:56:26.791 voicemail message 0 PERSONAL_00000000000000000000002
5005 09/22 15:56:26.791 voicemail database 0 Request connection: inUse: 1, active: 3
5005 09/22 15:56:26.791 voicemail database 0 Got connection: 1, inUse: 2, active: 3
5005 09/22 15:56:26.791 voicemail database 0 Request connection: inUse: 2, active: 3
5005 09/22 15:56:26.791 voicemail database 0 Got connection: 2, inUse: 3, active: 3
5005 09/22 15:56:26.791 voicemail database "SQL: " select vm_message.*, vm_usermsg.mailboxid, vm_usermsg.storetime, vm_usermsg.state from vm_usermsg, vm_message where vm_usermsg.messageid=vm_message.messageid and mailboxid='PERSONAL_00000000000000000000002' and  ((uid >= 79 and uid <= 79) ) order by uid asc ;
5005 09/22 15:56:26.799 voicemail message "Creating Message" FTX1036A36Q-NM-FOC090920DK-1222110362141
5005 09/22 15:56:26.800 voicemail database "Database query results" FTX1036A36Q-NM-FOC090920DK-1222110362141,1,1,1101,f,f,2447,19578,1222113360194,null,17876,22-Sep-08 19:56:00 UTC,9223372036854775807,1222113360194,0,0,t,2447,79,,PERSONAL_00000000000000000000002,1222113360194,1
5005 09/22 15:56:26.800 voicemail message 0 Message Properties msgId FTX1036A36Q-NM-FOC090920DK-1222110362141 msgUID 79
5005 09/22 15:56:26.800 voicemail database 0 Freed connection: 2, inUse: 2, active: 3
5005 09/22 15:56:27.231 voicemail database "SQL: " select uid from vm_message where messageid='FTX1036A36Q-NM-FOC090920DK-1222110362141';
5005 09/22 15:56:27.239 voicemail database 0 Freed connection: 1, inUse: 1, active: 3
5005 09/22 15:56:27.239 voicemail mailbox 0 adjust: msgId=FTX1036A36Q-NM-FOC090920DK-1222110362141, new -> saved
5005 09/22 15:56:27.239 voicemail mailbox 0 adjust: VOICE, new, urgent=false, recent=false, -1
5005 09/22 15:56:27.239 voicemail mailbox 0 adjust: VOICE_NEW, -1
5005 09/22 15:56:27.239 voicemail mailbox 0 adjust: VOICE, saved, urgent=false, recent=false, 1
5005 09/22 15:56:27.239 voicemail mailbox 0 adjust: VOICE_OLD, 1
5005 09/22 15:56:27.239 voicemail mailbox 0 adjust: voice=0/14 (0/0), fax=0/0 (0/0), bcst=0, deleted=0, recent=0, future=0
5005 09/22 15:56:27.241 voicemail mwi "setMessageWaiting" 0x0000000000000000 82011100,false
5005 09/22 15:56:27.264 voicemail mwi " job state" MessageWaitingThread.addJob:
Messages-Waiting: no
Message-Account: sip:82011100@14.86.30.2
Voice-Message: 0/14 (0/0)
Fax-Message: 0/0 (0/0)

X-Cisco-Message-State: saved
X-Cisco-Message-Type: normal
X-Cisco-Message-URI: imap://14.86.30.2/~gpburdell/INBOX/;UID=79
From: <sip:1101@sip.invalid>
To: "gpburdell" <sip:82011100@sip.invalid>
Date: Mon, 22 Sep 2008 19:56:00 GMT
Message-ID: FTX1036A36Q-NM-FOC090920DK-1222110362141
Message-Context: voice-message
Content-Duration: 2

5005 09/22 15:56:27.264 voicemail mwi " job state" MessageWaitingThread.addJob: numJobs=1
5005 09/22 15:56:27.264 voicemail mailbox "Message saved" Message state changed from 1 to 2
3940 09/22 15:56:27.270 voicemail mwi " job state" MessageWaitingThread.run: extn=82011100, numJobs=0
3940 09/22 15:56:27.271 voicemail mwi " job state" http://localhost:8080/mwiapp?extn=82011100&state=0
5754 09/22 15:56:27.279 ACCN HTTS 0 -> AppsInt.requestMap(/mwiapp):ENTER
5754 09/22 15:56:27.279 ACCN HTTS 0 -> AppsInt.requestMap(/mwiapp):EXIT(0)
5754 09/22 15:56:27.279 ACCN HTTS 0 -> AInvoker.doGet() (/mwiapp) ENTER
5754 09/22 15:56:27.279 ACCN HTTS 0 ApplicationInvoker URI=/mwiapp
5754 09/22 15:56:27.279 ACCN COMG 0 ContactStubImpl is constructed, id=18,type=Cisco Http Contact,impl id=null
5754 09/22 15:56:27.279 ACCN CHMG 0 ChMgrImpl::defineStub() - defining channel stub ...
5754 09/22 15:56:27.280 ACCN CHMG 0 ChStubImpl::ChannelStubImpl - Channel created successfully,id-0
5754 09/22 15:56:27.280 ACCN CHMG 0 ChannelStubImpl::setState() -id=0 setting channel state to IDLE
5754 09/22 15:56:27.281 ACCN CHMG 0 CHANNEL_STATE_CHANGE:Channel has changed state: Channel=null,Channel Class=com.cisco.http.HttpControlChannel,Channel Type=Cisco Http Channel,Channel id=0,Channel implementation id=0,Old state=unknown,New state=IDLE
5754 09/22 15:56:27.282 ACCN COMG 0 getApplicationPrivilege(): Privilege for contact: 18 is:1
5754 09/22 15:56:27.283 ACCN CHMG 0 CHANNEL_STATE_CHANGE:Channel has changed state: Channel=null,Channel Class=com.cisco.http.HttpControlChannel,Channel Type=Cisco Http Channel,Channel id=0,Channel implementation id=0,Old state=IDLE,New state=IN_USE
5754 09/22 15:56:27.283 ACCN CHMG 0 ChStubImpl:handleInUseTransition - notifying all waiting threads that channel is no longer idle-ChannelStub[channelClass=com.cisco.http.HttpControlChannel,type=Cisco Http Channel,id=0,state=IN_USE,pendingState=null,groupId=,locked=false]
5754 09/22 15:56:27.284 ACCN HTTS 0 -> LtdSemaph [589308704] permits: 0 limit: 1
5754 09/22 15:56:27.284 ACCN HTTS 0 -> HttpTrigger( getTriggerMap %2Fmwiapp, {secondaryDialogGroup=0, primaryDialogGroup=0}
5754 09/22 15:56:27.284 LLMA LAPI 0 Llama: getMaxIvrPortCount():
5754 09/22 15:56:27.285 LLMA LSDB 0 Llama: getMaxIvrPortCount(): LlamaSysdbUser(): getInt(): Getting int /sw/apps/limitsManager/ivrPort/query/maxCount
2815 09/22 15:56:27.287 LLMA LIVR 0 LlamaIvrPortQuery: get(): maxCount
5754 09/22 15:56:27.288 LLMA LSDB 0 Llama: getMaxIvrPortCount(): LlamaSysdbUser(): getInt(): Getting int /sw/apps/limitsManager/ivrPort/query/maxCount returns 0
5754 09/22 15:56:27.288 LLMA LAPI 0 Llama: getMaxIvrPortCount(): count: 0
2804 09/22 15:56:27.290 WFSP SCRP 0 WFSysdbNdScript::get enter
2804 09/22 15:56:27.290 WFSP SCRP 0 WFSysdbNdScript::get attribute=privilege
2804 09/22 15:56:27.291 WFSP SCRP 0 WFSysdbNdScript::get exit
5754 09/22 15:56:27.294 ACCN APMG 0 TASK_CREATED:Application task created: Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],Application Trigger=ContactApplicationTrigger[time=1222113387284,contact=HttpContact[id=18,type=Cisco Http Contact,implId=null,active=true,state=CONTACT_RECEIVED,inbound=true,handled=false,locale=en_US,aborting=false,app=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],task=null,session=null,seqNum=-1,time=1222113387279,req=org.apache.tomcat.facade.HttpServletRequestFacade@39c039c0]],Task id=17,000,000,019,Task Class=com.cisco.wfframework.engine.core.WFEngineWorkflowDebugTask,New Task Class=com.cisco.app.impl.WFWorkflowAppDebugTaskWrapper
5754 09/22 15:56:27.313 ACCN APMG 0 APP_SESSION_ACTIVE:Active application session: Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],Application Trigger=ContactApplicationTrigger[time=1222113387284,contact=HttpContact[id=18,type=Cisco Http Contact,implId=null,active=true,state=CONTACT_RECEIVED,inbound=true,handled=false,locale=en_US,aborting=false,app=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],task=null,session=null,seqNum=-1,time=1222113387279,req=org.apache.tomcat.facade.HttpServletRequestFacade@39c039c0]],Task id=17,000,000,019,Active Sessions=1,Max Sessions=8
5754 09/22 15:56:27.315 ACCN APMG 0 TASK_INIT:Application task initializing: Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],Application Trigger=ContactApplicationTrigger[time=1222113387284,contact=HttpContact[id=18,type=Cisco Http Contact,implId=null,active=true,state=CONTACT_RECEIVED,inbound=true,handled=false,locale=en_US,aborting=false,app=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],task=null,session=null,seqNum=-1,time=1222113387279,req=org.apache.tomcat.facade.HttpServletRequestFacade@39c039c0]],Task id=17,000,000,019,Task Class=class com.cisco.app.impl.WFWorkflowAppDebugTaskWrapper
5754 09/22 15:56:27.317 ACCN APMG 0 TASK_STARTING:Application task starting: Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],Application Trigger=ContactApplicationTrigger[time=1222113387284,contact=HttpContact[id=18,type=Cisco Http Contact,implId=null,active=true,state=CONTACT_RECEIVED,inbound=true,handled=false,locale=en_US,aborting=false,app=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],task=17000000019,session=null,seqNum=-1,time=1222113387279,req=org.apache.tomcat.facade.HttpServletRequestFacade@39c039c0]],Task id=17,000,000,019,Task Class=class com.cisco.app.impl.WFWorkflowAppDebugTaskWrapper
5754 09/22 15:56:27.319 ACCN ENGN 0 Execute Task 17000000019
>>>>> Before execution
An object of com.cisco.app.impl.WFWorkflowAppDebugTaskWrapper
State: STARTED
Application: App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]]
Trigger: ContactApplicationTrigger[time=1222113387284,contact=HttpContact[id=18,type=Cisco Http Contact,implId=null,active=true,state=CONTACT_RECEIVED,inbound=true,handled=false,locale=en_US,aborting=false,app=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],task=17000000019,session=null,seqNum=-1,time=1222113387279,req=org.apache.tomcat.facade.HttpServletRequestFacade@39c039c0]]
An object of com.cisco.wfframework.engine.core.WFEngineWorkflowDebugTask
ID: 17000000019
Start time (ms): 1222113387292
Source ID:
Destination ID:
Media Instance ID: null
Session handled: false
Context:
An object of com.cisco.wfframework.obj.WFWorkflowContext
{
   {strDeviceNum, java.lang.String, }
   {strMWI_DN, java.lang.String, }
   {errorFileNoParameter, java.lang.String, MWIerrorNoParam.html}
   {successFile, java.lang.String, MWIsuccess.html}
   {errorFileCreateCallFail, java.lang.String, MWIerrorCreateCallFail.html}
   {returnFileDocument, com.cisco.doc.Document, null}
   {strMWI_CompleteNum, java.lang.String, }
   {rnaTimeOut, java.lang.Integer, 5}
   {CallControlGroupID, java.lang.Integer, 0}
   {mwiCallContact, com.cisco.contact.Contact, null}
   {mwiOn, java.lang.Boolean, true}
   {strMWI_ON_DN, java.lang.String, 8000}
   {strMWI_OFF_DN, java.lang.String, 8001}
   {mwistatus, java.lang.String, }
   {CallControlGroupID_ITS, java.lang.Integer, 0}
   {Real_CallControlGroupID, java.lang.Integer, 1}
   {sipMWIMethod, java.lang.String, }
   {allowUnsolicited, java.lang.Boolean, true}
   {mwiBody, com.cisco.doc.Document, null}
   {i, java.lang.Integer, 1}
   {comma, java.lang.String, ,}
   {mwiMethod, java.lang.String, }
   {outcall, java.lang.Boolean, false}
}
Private Context:
An object of com.cisco.wfframework.obj.WFWorkflowContext
{
}
Number of executed steps: 0
Current step: Start
<<<<<

5754 09/22 15:56:27.321 ACCN APMG 0 EXECUTING_STEP:Executing a step: Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],Task id=17,000,000,019,Step id=0,Step Class=com.cisco.wfframework.steps.core.StepStart,Step Description=Start
5754 09/22 15:56:27.321 ACCN ENGN 0 Execute step of Task 17000000019 : Start
5754 09/22 15:56:27.323 ACCN APMG 0 EXECUTING_STEP:Executing a step: Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],Task id=17,000,000,019,Step id=1,Step Class=com.cisco.wf.steps.ivr.AcceptStep,Step Description=Accept (contact: --Triggering Contact--)
5754 09/22 15:56:27.324 ACCN ENGN 0 Execute step of Task 17000000019 : Accept (contact: --Triggering Contact--)
5754 09/22 15:56:27.325 ACCN APMG 0 EXECUTING_STEP:Executing a step: Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],Task id=17,000,000,019,Step id=377,Step Class=com.cisco.wf.steps.http.GetHttpHeaderStep,Step Description=Get Http Contact Info (contact: --Triggering Contact--)
5754 09/22 15:56:27.326 ACCN ENGN 0 Execute step of Task 17000000019 : Get Http Contact Info (contact: --Triggering Contact--)
5754 09/22 15:56:27.328 ACCN APMG 0 EXECUTING_STEP:Executing a step: Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],Task id=17,000,000,019,Step id=142,Step Class=com.cisco.wfframework.steps.core.StepIf,Step Description=If ( mwistatus != "0" ) Then
5754 09/22 15:56:27.328 ACCN ENGN 0 Execute step of Task 17000000019 : If ( mwistatus != "0" ) Then
5754 09/22 15:56:27.330 ACCN APMG 0 EXECUTING_STEP:Executing a step: Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],Task id=17,000,000,019,Step id=145,Step Class=com.cisco.wfframework.steps.core.StepAssign,Step Description=Set strMWI_DN = strMWI_OFF_DN
5754 09/22 15:56:27.330 ACCN ENGN 0 Execute step of Task 17000000019 : Set strMWI_DN = strMWI_OFF_DN
5754 09/22 15:56:27.332 ACCN APMG 0 EXECUTING_STEP:Executing a step: Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],Task id=17,000,000,019,Step id=146,Step Class=com.cisco.wfframework.steps.core.StepAssign,Step Description=Set mwiOn = false
5754 09/22 15:56:27.332 ACCN ENGN 0 Execute step of Task 17000000019 : Set mwiOn = false
5754 09/22 15:56:27.334 ACCN APMG 0 EXECUTING_STEP:Executing a step: Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],Task id=17,000,000,019,Step id=78,Step Class=com.cisco.wfframework.steps.core.StepIf,Step Description=If ( mwistatus != "" ) Then
5754 09/22 15:56:27.334 ACCN ENGN 0 Execute step of Task 17000000019 : If ( mwistatus != "" ) Then
5754 09/22 15:56:27.336 ACCN APMG 0 EXECUTING_STEP:Executing a step: Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],Task id=17,000,000,019,Step id=83,Step Class=com.cisco.wfframework.steps.core.StepIf,Step Description=If ( strDeviceNum != "" ) Then
5754 09/22 15:56:27.336 ACCN ENGN 0 Execute step of Task 17000000019 : If ( strDeviceNum != "" ) Then
5754 09/22 15:56:27.338 ACCN APMG 0 EXECUTING_STEP:Executing a step: Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],Task id=17,000,000,019,Step id=378,Step Class=com.cisco.wf.steps.ivr.MWIStep,Step Description=Set Message Waiting Indicator (DN: strDeviceNum)
5754 09/22 15:56:27.338 ACCN ENGN 0 Execute step of Task 17000000019 : Set Message Waiting Indicator (DN: strDeviceNum)
5754 09/22 15:56:27.338 ACCN STCC 0 Task:17000000019 Executing MWIStep
5754 09/22 15:56:27.338 ACCN CHMG 0 ChMgrImpl:getGroup - got following group GroupStub[channelClass=com.cisco.wf.subsystems.jtapi.JTAPICallControlChannel,type=Cisco CTI Port,id=1,name=1,state=IN_SERVICE,channel=8]
5754 09/22 15:56:27.338 ACCN TELS 0 setMessageWaiting: dn=82011100 bool=false
5754 09/22 15:56:27.338 ACCN TELS 0 Looking for an inservice port for mwi:TP[type=Cisco CTI Port,id=7,implId=82011080,active=false,state=IDLE]
5754 09/22 15:56:27.339 ACCN TELS 0 Found inservice port:TP[type=Cisco CTI Port,id=7,implId=82011080,active=false,state=IDLE]
3675 09/22 15:56:27.344 ACCN LMED 0 PromptPlayer::closeStream
3675 09/22 15:56:27.346 ACCN LMED 0 PromptPlayer::closing outputSink
3675 09/22 15:56:27.346 ACCN LMED 0 PromptPlayer::resetSources
3675 09/22 15:56:27.346 ACCN LMED 0 PromptPlayer::rtpData close
3675 09/22 15:56:27.346 ACCN LMED 0 PromptPlayer::closeStream done
5754 09/22 15:56:27.355 ACCN STCC 0 Task:17000000019 Executing MWIStep ends.
5754 09/22 15:56:27.356 ACCN APMG 0 EXECUTING_STEP:Executing a step: Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],Task id=17,000,000,019,Step id=379,Step Class=com.cisco.wfframework.steps.core.StepAssign,Step Description=Set allowUnsolicited = false
5754 09/22 15:56:27.357 ACCN ENGN 0 Execute step of Task 17000000019 : Set allowUnsolicited = false
5754 09/22 15:56:27.358 ACCN APMG 0 EXECUTING_STEP:Executing a step: Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],Task id=17,000,000,019,Step id=380,Step Class=com.cisco.wf.steps.io.CreateFileDocStep,Step Description=Create File Document
5754 09/22 15:56:27.359 ACCN ENGN 0 Execute step of Task 17000000019 : Create File Document
5754 09/22 15:56:27.369 ACCN APMG 0 EXECUTING_STEP:Executing a step: Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],Task id=17,000,000,019,Step id=346,Step Class=com.cisco.wfframework.steps.core.StepIf,Step Description=If ( allowUnsolicited == true ) Then
5754 09/22 15:56:27.369 ACCN ENGN 0 Execute step of Task 17000000019 : If ( allowUnsolicited == true ) Then
5754 09/22 15:56:27.370 ACCN APMG 0 EXECUTING_STEP:Executing a step: Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],Task id=17,000,000,019,Step id=383,Step Class=com.cisco.wf.steps.ivr.MWIStep,Step Description=Set Message Waiting Indicator (DN: strDeviceNum)
5754 09/22 15:56:27.371 ACCN ENGN 0 Execute step of Task 17000000019 : Set Message Waiting Indicator (DN: strDeviceNum)
5754 09/22 15:56:27.371 ACCN STCC 0 Task:17000000019 Executing MWIStep
5754 09/22 15:56:27.371 ACCN CHMG 0 ChMgrImpl:getGroup - got following group GroupStub[channelClass=com.cisco.wf.subsystems.callcontrol.sip.SIPCallControlChannel,type=Cisco SIP Channel,id=0,name=0,state=IN_SERVICE,channel=9]
5754 09/22 15:56:27.371 ACCN SIPS 0 setMessageWaiting: genSubNot=false, genUnsolicited=false, dn=82011100
5754 09/22 15:56:27.371 ACCN SIPS 0 neither sub-notify or unsolicited is enabled
5754 09/22 15:56:27.371 ACCN STCC 0 Task:17000000019 Executing MWIStep ends.
5754 09/22 15:56:27.372 ACCN APMG 0 EXECUTING_STEP:Executing a step: Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],Task id=17,000,000,019,Step id=425,Step Class=com.cisco.wf.steps.io.CreateFileDocStep,Step Description=Create File Document
5754 09/22 15:56:27.373 ACCN ENGN 0 Execute step of Task 17000000019 : Create File Document
5754 09/22 15:56:27.383 ACCN APMG 0 EXECUTING_STEP:Executing a step: Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],Task id=17,000,000,019,Step id=339,Step Class=com.cisco.wfframework.steps.core.StepLabel,Step Description=SEND_RESPONSE:
5754 09/22 15:56:27.383 ACCN ENGN 0 Execute step of Task 17000000019 : SEND_RESPONSE:
5754 09/22 15:56:27.385 ACCN APMG 0 EXECUTING_STEP:Executing a step: Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],Task id=17,000,000,019,Step id=341,Step Class=com.cisco.wf.steps.http.StepSendHTTP,Step Description=Send Response (contact: --Triggering Contact--, document: returnFileDocument)
5754 09/22 15:56:27.385 ACCN ENGN 0 Execute step of Task 17000000019 : Send Response (contact: --Triggering Contact--, document: returnFileDocument)
5754 09/22 15:56:27.388 ACCN CHMG 0 ChStubImpl:handleIdleTransition - channel currently InUse - removing channel from contact-ChannelStub[channelClass=com.cisco.http.HttpControlChannel,type=Cisco Http Channel,id=0,state=IN_USE,pendingState=null,groupId=,locked=false]
5754 09/22 15:56:27.390 ACCN CHMG 0 CHANNEL_STATE_CHANGE:Channel has changed state: Channel=null,Channel Class=com.cisco.http.HttpControlChannel,Channel Type=Cisco Http Channel,Channel id=0,Channel implementation id=0,Old state=IN_USE,New state=IDLE
5754 09/22 15:56:27.391 ACCN CHMG 0 CHANNEL_STATE_CHANGE:Channel has changed state: Channel=null,Channel Class=com.cisco.http.HttpControlChannel,Channel Type=Cisco Http Channel,Channel id=0,Channel implementation id=0,Old state=IDLE,New state=DISPOSED
5754 09/22 15:56:27.392 ACCN CHMG 0 ChStubImpl:handleDisposedTransition - notifying all waiting threads that channel is no longer idle-ChannelStub[channelClass=com.cisco.http.HttpControlChannel,type=Cisco Http Channel,id=0,state=DISPOSED,pendingState=null,groupId=,locked=false]
5754 09/22 15:56:27.393 ACCN APMG 0 EXECUTING_STEP:Executing a step: Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],Task id=17,000,000,019,Step id=120,Step Class=com.cisco.wfframework.steps.core.StepEnd,Step Description=End
5754 09/22 15:56:27.393 ACCN ENGN 0 Execute step of Task 17000000019 : End
5754 09/22 15:56:27.396 ACCN ENGN 0 >>>>> After execution
An object of com.cisco.app.impl.WFWorkflowAppDebugTaskWrapper
State: STARTED
Application: App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]]
Trigger: ContactApplicationTrigger[time=1222113387284,contact=HttpContact[id=18,type=Cisco Http Contact,implId=null,active=false,state=CONTACT_TERMINATED,inbound=true,handled=false,locale=en_US,aborting=false,app=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],task=17000000019,session=null,seqNum=-1,time=1222113387279,req=org.apache.tomcat.facade.HttpServletRequestFacade@39c039c0]]
An object of com.cisco.wfframework.engine.core.WFEngineWorkflowDebugTask
ID: 17000000019
Start time (ms): 1222113387292
Source ID:
Destination ID:
Media Instance ID: null
Session handled: false
Context:
An object of com.cisco.wfframework.obj.WFWorkflowContext
{
   {strDeviceNum, java.lang.String, 82011100}
   {strMWI_DN, java.lang.String, 8001}
   {errorFileNoParameter, java.lang.String, MWIerrorNoParam.html}
   {successFile, java.lang.String, MWIsuccess.html}
   {errorFileCreateCallFail, java.lang.String, MWIerrorCreateCallFail.html}
   {returnFileDocument, com.cisco.doc.Document, FileDocument[file=/usr/wfavvid/Documents/Generic/system/default/MWIsuccess.html,mime=text/html]}
   {strMWI_CompleteNum, java.lang.String, }
   {rnaTimeOut, java.lang.Integer, 5}
   {CallControlGroupID, java.lang.Integer, 0}
   {mwiCallContact, com.cisco.contact.Contact, null}
   {mwiOn, java.lang.Boolean, false}
   {strMWI_ON_DN, java.lang.String, 8000}
   {strMWI_OFF_DN, java.lang.String, 8001}
   {mwistatus, java.lang.String, 0}
   {CallControlGroupID_ITS, java.lang.Integer, 0}
   {Real_CallControlGroupID, java.lang.Integer, 1}
   {sipMWIMethod, java.lang.String, }
   {allowUnsolicited, java.lang.Boolean, false}
   {mwiBody, com.cisco.doc.Document, CachedDocument[name=null,mime=application/simple-message-summary]}
   {i, java.lang.Integer, 1}
   {comma, java.lang.String, ,}
   {mwiMethod, java.lang.String, }
   {outcall, java.lang.Boolean, false}
}
Private Context:
An object of com.cisco.wfframework.obj.WFWorkflowContext
{
}
Number of executed steps: 17
Current step: End
<<<<<

5754 09/22 15:56:27.398 ACCN APMG 0 TASK_ENDED:Application task ended: Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],Application Trigger=ContactApplicationTrigger[time=1222113387284,contact=HttpContact[id=18,type=Cisco Http Contact,implId=null,active=false,state=CONTACT_TERMINATED,inbound=true,handled=false,locale=en_US,aborting=false,app=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],task=17000000019,session=null,seqNum=-1,time=1222113387279,req=org.apache.tomcat.facade.HttpServletRequestFacade@39c039c0]],Task id=17,000,000,019,Task Class=class com.cisco.app.impl.WFWorkflowAppDebugTaskWrapper
5754 09/22 15:56:27.401 ACCN APMG 0 APP_SESSION_IDLE:Idle application session: Application=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],Application Trigger=ContactApplicationTrigger[time=1222113387284,contact=HttpContact[id=18,type=Cisco Http Contact,implId=null,active=false,state=CONTACT_TERMINATED,inbound=true,handled=false,locale=en_US,aborting=false,app=App[name=ciscomwiapplication,type=Cisco Script Application,id=0,desc=ciscomwiapplication,enabled=true,max=8,valid=true,optional=[cfgVars=[Lcom.cisco.wfapi.util.WFNameValuePair;@35763576,privilegeType=1,last.modified=1219851816864,script=setmwi.aef]],task=17000000019,session=null,seqNum=-1,time=1222113387279,req=org.apache.tomcat.facade.HttpServletRequestFacade@39c039c0]],Task id=17,000,000,019,Active Sessions=0,Max Sessions=8
5754 09/22 15:56:27.401 ACCN ENGN 0 Notifying Debug task Ended
5754 09/22 15:56:27.401 ACCN HTTS 0 -> LtdSemaph [589308704] permits: 1 limit: 1
5754 09/22 15:56:27.401 ACCN HTTS 0 -> AInvoker.doGet() (/mwiapp) EXIT
5005 09/22 15:56:28.127 voicemail message 0 PERSONAL_00000000000000000000002
5005 09/22 15:56:28.127 voicemail database 0 Request connection: inUse: 1, active: 3
5005 09/22 15:56:28.127 voicemail database 0 Got connection: 2, inUse: 2, active: 3
5005 09/22 15:56:28.127 voicemail database 0 Request connection: inUse: 2, active: 3
5005 09/22 15:56:28.127 voicemail database 0 Got connection: 1, inUse: 3, active: 3
5005 09/22 15:56:28.127 voicemail database "SQL: " select vm_message.*, vm_usermsg.mailboxid, vm_usermsg.storetime, vm_usermsg.state from vm_usermsg, vm_message where vm_usermsg.messageid=vm_message.messageid and mailboxid='PERSONAL_00000000000000000000002' and  ((uid >= 67 and uid <= 67) ) order by uid asc ;
5005 09/22 15:56:28.135 voicemail message "Creating Message" FTX1036A371-NM-FOC092233LG-1220973796303
5005 09/22 15:56:28.136 voicemail database "Database query results" FTX1036A371-NM-FOC092233LG-1220973796303,1,2,82211105@br2211.cue.com,f,f,4947,39578,1221160112000,null,17826,11-Sep-08 19:08:32 UTC,9223372036854775807,1221160115477,0,0,t,4947,67,82214105,PERSONAL_00000000000000000000002,1221161239281,2
5005 09/22 15:56:28.136 voicemail message 0 Message Properties msgId FTX1036A371-NM-FOC092233LG-1220973796303 msgUID 67
5005 09/22 15:56:28.136 voicemail database 0 Freed connection: 1, inUse: 2, active: 3
5005 09/22 15:56:28.136 voicemail database 0 Freed connection: 2, inUse: 1, active: 3
5005 09/22 15:56:28.179 voicemail message 0 PERSONAL_00000000000000000000002
5005 09/22 15:56:28.179 voicemail database 0 Request connection: inUse: 1, active: 3
5005 09/22 15:56:28.180 voicemail database 0 Got connection: 1, inUse: 2, active: 3
5005 09/22 15:56:28.180 voicemail database 0 Request connection: inUse: 2, active: 3
5005 09/22 15:56:28.180 voicemail database 0 Got connection: 2, inUse: 3, active: 3
5005 09/22 15:56:28.180 voicemail database "SQL: " select vm_message.*, vm_usermsg.mailboxid, vm_usermsg.storetime, vm_usermsg.state from vm_usermsg, vm_message where vm_usermsg.messageid=vm_message.messageid and mailboxid='PERSONAL_00000000000000000000002' and  ((uid >= 67 and uid <= 67) ) order by uid asc ;
5005 09/22 15:56:28.187 voicemail message "Creating Message" FTX1036A371-NM-FOC092233LG-1220973796303
5005 09/22 15:56:28.188 voicemail database "Database query results" FTX1036A371-NM-FOC092233LG-1220973796303,1,2,82211105@br2211.cue.com,f,f,4947,39578,1221160112000,null,17826,11-Sep-08 19:08:32 UTC,9223372036854775807,1221160115477,0,0,t,4947,67,82214105,PERSONAL_00000000000000000000002,1221161239281,2
5005 09/22 15:56:28.188 voicemail message 0 Message Properties msgId FTX1036A371-NM-FOC092233LG-1220973796303 msgUID 67
5005 09/22 15:56:28.188 voicemail database 0 Freed connection: 2, inUse: 2, active: 3
5005 09/22 15:56:28.188 voicemail database 0 Freed connection: 1, inUse: 1, active: 3
6475
Views
0
Helpful
0
Comments