Buy or Renew
Buy or Renew
Cisco + Splunk: It’s a new day for your data. Learn more.
 
cancel
Turn on suggestions
Auto-suggest helps you quickly narrow down your search results by suggesting possible matches as you type.
Showing results for 
Search instead for 
Did you mean: 
cancel
Create a new article
9709
Views
10
Helpful
0
Comments

Message Waiting Indicator (MWI) Traces

Markus Schneider
Cisco Employee
Cisco Employee

‎06-10-2009 03:41 AM - edited ‎03-12-2019 08:08 AM

 

 

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
Labels:
Getting Started

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

Customers Also Viewed These Support Documents