FXO always busy tone

[Joan ma Mauri barbosa]

Hi folks,

I am having a lot of issues setting up 6 FXOs on a 2901 GW running CME 8.6... The FXOs are in Nigeria. I have tryied LS and GS signaling (even though I am pretty sure it is LS), tryed different impedances and other parameters... So far the line goes "off-hook" for 1 seconds, I get a busy tone and then it goes back to "on-hook".

The only thing I am not sure is if they are using 2 or 4 pair wires... I've read that you should not use 4 wire cables as they can cause busy outs... only the central pair is used anyway, right ?

Any suggestions ?

Thanks!

[Bruno Rangel]

Have you configured Cptone under Voice Port?

Please Post your relevand config...

Cheers
Bruno Rangel

"Se você quiser alguém em quem confiar, confie em si mesmo. Quem acredita sempre alcança"
Renato Russo

[Joan ma Mauri barbosa]

Hi Bruno,

Sure, this is just one port.. the rest are the same:

!

voice-port 0/0/0

trunk-group POTS

cptone NG

connection plar 8296

caller-id enable

!

I'v also tryied different impedances...

[Bruno Rangel]

HiJoan

Try this see if works:

voice-port 0/0/0

trunk-group POTS

cptone NG

timing sup-disconnect 85

impedance complex3

Cheers
Bruno Rangel

"Se você quiser alguém em quem confiar, confie em si mesmo. Quem acredita sempre alcança"
Renato Russo

[Kevin Monteiro]

Hi Joan,

Try re-creating the issue and capture the following debugs:

debug voip ccapi inout

debug vpm signal

debug voip ccap inout

Let me know the same.

-Regards,

Kevin

[Joan ma Mauri barbosa]

Hi Kevin,

I think the provider's equiment is faulty or not delivering enough voltage...  Taking a look a the debug vpm signal I see a "

[0/0/0, FXOLS_WAIT_DIAL_TONE, E_DSP_SIG_1100]fxols_power_denial_detected"

The customer assures that with a regular phone the line works.. What do you think ? and THANK YOU

Carlyle_VGW#

May  2 16:27:31.911: htsp_process_event: [50/0/9.1, EFXS_ONHOOK, E_DSP_SIG_1100]efxs_onhook_offhook htsp_setup_ind

May  2 16:27:31.911: [50/0/9.1] get_local_station_id calling num=8998 calling name=Guest4 calling time=05/02 17:27  orig called=

May  2 16:27:31.915: htsp_process_event: [50/0/9.1, EFXS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]efxs_check_auto_call

May  2 16:27:32.719: htsp_digit_ready(50/0/9.1): digit = 9

May  2 16:27:32.719: htsp_digit_ready(50/0/9.1): digit = 1

May  2 16:27:32.719: htsp_digit_ready(50/0/9.1): digit = 2

May  2 16:27:32.979: htsp_digit_ready(50/0/9.1): digit = 7

May  2 16:27:32.979: htsp_digit_ready(50/0/9.1): digit = 7

May  2 16:27:33.435: htsp_digit_ready(50/0/9.1): digit = 8

May  2 16:27:33.435: htsp_digit_ready(50/0/9.1): digit = 2

May  2 16:27:33.435: htsp_digit_ready(50/0/9.1): digit = 9

May  2 16:27:33.695: htsp_digit_ready(50/0/9.1): digit = 4

May  2 16:27:38.695: htsp_timer_stop3

May  2 16:27:38.695: htsp_process_event: [50/0/9.1, EFXS_OFFHOOK, E_HTSP_PROCEEDING]efxs_offhook_proceeding

May  2 16:27:38.695: [50/0/9.1] set signal state = 0x8 timestamp = 0htsp_setup_req

May  2 16:27:38.695: htsp_process_event: [0/0/0, FXOLS_ONHOOK, E_HTSP_SETUP_REQ]fxols_onhook_setup

May  2 16:27:38.695: [0/0/0] set signal state = 0xC timestamp = 0

May  2 16:27:38.695: htsp_timer - 1300 msec

May  2 16:27:38.951: htsp_process_event: [0/0/0, FXOLS_WAIT_DIAL_TONE, E_DSP_SIG_1100]fxols_power_denial_detected

May  2 16:27:38.951: htsp_timer2 - 1000 msec

May  2 16:27:38.951: htsp_timer_stop

May  2 16:27:39.951: htsp_process_event: [0/0/0, FXOLS_WAIT_DIAL_TONE, E_HTSP_EVENT_TIMER2]fxols_power_den_disc

May  2 16:27:39.951: htsp_timer_stop

May  2 16:27:39.951: htsp_timer_stop2

May  2 16:27:39.951: [0/0/0] set signal state = 0x4 timestamp = 0

May  2 16:27:39.951: htsp_process_event: [0/0/0, FXOLS_ONHOOK, E_HTSP_RELEASE_REQ]fxols_onhook_release

Carlyle_VGW#

May  2 16:28:09.951: htsp_process_event: [50/0/9.1, EFXS_OFFHOOK, E_HTSP_RELEASE_REQ]efxs_offhook_disc

May  2 16:28:09.951: htsp_timer_stop

May  2 16:28:09.951: [50/0/9.1] set signal state = 0x4 timestamp = 0

May  2 16:28:09.951: [50/0/9.1] set signal state = 0xC timestamp = 0

May  2 16:28:09.951: [50/0/9.1] set signal state = 0x4 timestamp = 10

May  2 16:28:09.951: htsp_timer - 10 msec

May  2 16:28:09.963: htsp_process_event: [50/0/9.1, EFXS_CPC, E_HTSP_EVENT_TIMER]efxs_cpc_timer

May  2 16:28:09.963: htsp_timer - 30000 msec

May  2 16:28:09.963: htsp_process_event: [50/0/9.1, EFXS_WAIT_ONHOOK, E_DSP_SIG_0100]efxs_waitonhook_onhook

May  2 16:28:09.963: htsp_timer_stop htsp_report_onhook_sigCarlyle_VGW#
May  2 16:27:31.911: htsp_process_event: [50/0/9.1, EFXS_ONHOOK, E_DSP_SIG_1100]efxs_onhook_offhook htsp_setup_ind
May  2 16:27:31.911: [50/0/9.1] get_local_station_id calling num=8998 calling name=Guest4 calling time=05/02 17:27  orig called=
May  2 16:27:31.915: htsp_process_event: [50/0/9.1, EFXS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]efxs_check_auto_call
May  2 16:27:32.719: htsp_digit_ready(50/0/9.1): digit = 9
May  2 16:27:32.719: htsp_digit_ready(50/0/9.1): digit = 1
May  2 16:27:32.719: htsp_digit_ready(50/0/9.1): digit = 2
May  2 16:27:32.979: htsp_digit_ready(50/0/9.1): digit = 7
May  2 16:27:32.979: htsp_digit_ready(50/0/9.1): digit = 7
May  2 16:27:33.435: htsp_digit_ready(50/0/9.1): digit = 8
May  2 16:27:33.435: htsp_digit_ready(50/0/9.1): digit = 2
May  2 16:27:33.435: htsp_digit_ready(50/0/9.1): digit = 9
May  2 16:27:33.695: htsp_digit_ready(50/0/9.1): digit = 4
May  2 16:27:38.695: htsp_timer_stop3
May  2 16:27:38.695: htsp_process_event: [50/0/9.1, EFXS_OFFHOOK, E_HTSP_PROCEEDING]efxs_offhook_proceeding
May  2 16:27:38.695: [50/0/9.1] set signal state = 0x8 timestamp = 0htsp_setup_req
May  2 16:27:38.695: htsp_process_event: [0/0/0, FXOLS_ONHOOK, E_HTSP_SETUP_REQ]fxols_onhook_setup
May  2 16:27:38.695: [0/0/0] set signal state = 0xC timestamp = 0
May  2 16:27:38.695: htsp_timer - 1300 msec
May  2 16:27:38.951: htsp_process_event: [0/0/0, FXOLS_WAIT_DIAL_TONE, E_DSP_SIG_1100]fxols_power_denial_detected
May  2 16:27:38.951: htsp_timer2 - 1000 msec
May  2 16:27:38.951: htsp_timer_stop
May  2 16:27:39.951: htsp_process_event: [0/0/0, FXOLS_WAIT_DIAL_TONE, E_HTSP_EVENT_TIMER2]fxols_power_den_disc
May  2 16:27:39.951: htsp_timer_stop
May  2 16:27:39.951: htsp_timer_stop2
May  2 16:27:39.951: [0/0/0] set signal state = 0x4 timestamp = 0
May  2 16:27:39.951: htsp_process_event: [0/0/0, FXOLS_ONHOOK, E_HTSP_RELEASE_REQ]fxols_onhook_release
Carlyle_VGW#
May  2 16:28:09.951: htsp_process_event: [50/0/9.1, EFXS_OFFHOOK, E_HTSP_RELEASE_REQ]efxs_offhook_disc
May  2 16:28:09.951: htsp_timer_stop
May  2 16:28:09.951: [50/0/9.1] set signal state = 0x4 timestamp = 0
May  2 16:28:09.951: [50/0/9.1] set signal state = 0xC timestamp = 0
May  2 16:28:09.951: [50/0/9.1] set signal state = 0x4 timestamp = 10
May  2 16:28:09.951: htsp_timer - 10 msec
May  2 16:28:09.963: htsp_process_event: [50/0/9.1, EFXS_CPC, E_HTSP_EVENT_TIMER]efxs_cpc_timer
May  2 16:28:09.963: htsp_timer - 30000 msec
May  2 16:28:09.963: htsp_process_event: [50/0/9.1, EFXS_WAIT_ONHOOK, E_DSP_SIG_0100]efxs_waitonhook_onhook
May  2 16:28:09.963: htsp_timer_stop htsp_report_onhook_sig

[Ayodeji Okanlawon]

Joan,

I had a similar issue with power denial detected. When a phone is connected it works however you cant make calls. From memory i think it truned out to be a faulty cable/bad cable/wrong cable pair

Please rate all useful posts

"opportunity is a haughty goddess who waste no time with those who are unprepared"

[Kevin Monteiro]

Hi Juan,

Try adding the following command and shut no shut the FXO port:

config t

ME(config)#voice-port 0/2/0

CME(config-voiceport)#no b

CME(config-voiceport)#no bat

CME(config-voiceport)#no battery-reversal

CME(config-voiceport)#shu

CME(config-voiceport)#shut

CME(config-voiceport)#shutdown

CME(config-voiceport)#no shu

CME(config-voiceport)#no shutdown

http://www.cisco.com/en/US/tech/tk652/tk653/technologies_tech_note09186a00800ae2d1.shtml#topic5

This is the most common issue  FXO disconnect:

Power Denial-based Supervisory Disconnect

Power denial detection is an interruption of line power from the switch or PBX to the FXO port, which lasts at least 350 ms. The FXO interface on the router detects that power is no longer present and interprets this as a supervisory disconnect indication. This is available on the Cisco 1750, 2600, 3600, 3700 and MC3810 series router analog FXO ports in all versions of Cisco IOS which have voice support. This figure provides an illustration:

Battery Reversal

Battery reversal is implemented by reversing the battery polarity on the PBX. This is done initially when the call is connected (far-end answer), with the polarity reversed throughout the entire conversation. When the far-end disconnects, the battery polarity is changed back to normal to indicate call disconnect. PBX uses the battery reversal indication to start billing.

Note: Foreign Exchange Station (FXS) ports normally reverse the battery upon call connection. Therefore, if an FXS port is connected to an FXO port that does not support battery reversal detection, you should disable battery reversal on the FXS port to prevent unexpected behavior.

Kindly rate this post accordingly.

-Regards,

Kevin Monteiro

[Joan ma Mauri barbosa]

Hi Kevin,

That is the firts thing I tryied.. no luck.. Moreover, when I do an Inbound call I don't see anything at all on the debug vpm signal.. the port never tryies to go off-hook either

Thanks

[Kevin Monteiro]

Hi Joan,

if you dont mind can you attach the show tech with show voice port 0/0/0.

I would want tohave a look at it.

-Regards,

Kevin Monteiro

[Kevin Monteiro]

Hi Joan,

Along with the show tech and show voice port 0/0/0 i would require show voice dsp group all.

-Regards,

Kevin

[Joan ma Mauri barbosa]

Hi Kevin,

Here are the outputs except from the show tech because I am not allowed to share that output... :-(

#show voice dsp group all
DSP groups on slot 0:
dsp 1:
  State: UP, firmware: 28.3.5
  Max signal/voice channel: 16/16
  Max credits: 240, Voice credits: 240, Video credits: 0
  num_of_sig_chnls_allocated: 8
  Transcoding channels allocated: 2
  Group: FLEX_GROUP_VOICE, complexity: FLEX
    Shared credits: 192, reserved credits: 0
    Signaling channels allocated: 8
    Voice channels allocated: 0
    Credits used (rounded-up): 0
  Group: FLEX_GROUP_XCODE, complexity: HIGH
    Shared credits: 0, reserved credits: 48
    Transcoding channels allocated: 0
    Credits used (rounded-up): 0
  Slot: 0
  Device idx: 0
  PVDM Slot: 0
  Dsp Type: SP2600

DSP groups on slot 1:
This command is not applicable to slot 1

  0 DSP resource allocation failure

show voice port 0/0/0

Foreign Exchange Office 0/0/0 Slot is 0, Sub-unit is 0, Port is 0
Type of VoicePort is FXO
Operation State is DORMANT
Administrative State is UP
The Last Interface Down Failure Cause is Administrative Shutdown
Description is not set
Noise Regeneration is enabled
Non Linear Processing is enabled
Non Linear Mute is disabled
Non Linear Threshold is -21 dB
Music On Hold Threshold is Set to -38 dBm
In Gain is Set to 0 dB
Out Attenuation is Set to 3 dB
Echo Cancellation is enabled
Echo Cancellation NLP mute is disabled
Echo Cancellation NLP threshold is -21 dB
Echo Cancel Coverage is set to 128 ms
Echo Cancel worst case ERL is set to 6 dB
Playout-delay Mode is set to adaptive
Playout-delay Nominal is set to 60 ms
Playout-delay Maximum is set to 1000 ms
Playout-delay Minimum mode is set to default, value 40 ms
Playout-delay Fax is set to 300 ms
Connection Mode is plar
Connection Number is 8998
Initial Time Out is set to 15 s
Interdigit Time Out is set to 10 s
Call Disconnect Time Out is set to 60 s
Power Denial Disconnect Time Out is set to 1000 ms
Ringing Time Out is set to 180 s
Wait Release Time Out is set to 30 s
Companding Type is u-law
Region Tone is set for NG

Analog Info Follows:
Currently processing none
Maintenance Mode Set to None (not in mtc mode)
Number of signaling protocol errors are 0
Impedance is set to complex3 Ohm
Station name None, Station number None
Translation profile (Incoming):
Translation profile (Outgoing):
lpcor (Incoming):
lpcor (Outgoing):

Voice card specific Info Follows:
Signal Type is loopStart
Battery-Reversal is disabled
Number Of Rings is set to 1
Supervisory Disconnect is signal
Answer Supervision is inactive
Hook Status is On Hook
Ring Detect Status is inactive
Ring Ground Status is inactive
Tip Ground Status is inactive
Dial Out Type is dtmf
Digit Duration Timing is set to 100 ms
InterDigit Duration Timing is set to 100 ms
Pulse Rate Timing is set to 10 pulses/second
InterDigit Pulse Duration Timing is set to 750 ms
Percent Break of Pulse is 65 percent
GuardOut timer is 2000 ms
Minimum ring duration timer is 125 ms
Hookflash-in Timing is set to 600 ms
Hookflash-out Timing is set to 400 ms
Supervisory Disconnect Timing (loopStart only) is set to 85 ms
OPX Ring Wait Timing is set to 6000 ms
Secondary dialtone is disabled

[Kevin Monteiro]

Hi Joan,

I would just request you make a testcall and capture these debugs again.

Paste the debugs in the notepad.

debug voip ccapi inout

debug vpm signal

debug voip vtsp all

config t

logg buff 500000000 deb

no logg mon

no logg con

logg on

ter no mon

clear log

show log

Make a test call and capture the debugs.

-Regards,

Kevin

[Joan ma Mauri barbosa]

Here you go

=~=~=~=~=~=~=~=~=~=~=~= PuTTY log 2013.05.02 12:14:23 =~=~=~=~=~=~=~=~=~=~=~=

Carlyle_VGW#
Carlyle_VGW#debug voip ccapi inout
voip ccapi inout debugging is on
Carlyle_VGW#debug vpm signal
Voice Port Module signaling debugging is enabled
Carlyle_VGW#debug voip vtsp all
voip vtsp all debugging is on

Carlyle_VGW#ter
Carlyle_VGW#terminal mon
Carlyle_VGW#terminal monitor
Carlyle_VGW#
Carlyle_VGW#
Carlyle_VGW#
Carlyle_VGW#
Carlyle_VGW#
Carlyle_VGW#
Carlyle_VGW#
May  2 19:15:03.968: htsp_process_event: [50/0/9.1, EFXS_ONHOOK, E_DSP_SIG_1100]efxs_onhook_offhook htsp_setup_ind
May  2 19:15:03.968: [50/0/9.1] get_local_station_id calling num=8998 calling name=Guest4 calling time=05/02 20:15  orig called=
May  2 19:15:03.972: //-1/xxxxxxxxxxxx/VTSP:(50/0/9):-1:-1:-1/vtsp_allocate_cdb: 
   CDB=0x2A64EE18
May  2 19:15:03.972: //-1/xxxxxxxxxxxx/VTSP:(50/0/9):-1:-1:-1/vtsp_do_call_setup_ind: 
   Event=E_TSP_SETUP_IND
   Progress Indication=3, CarrierIDCode=, Info Trans Capability=0, Source Carrier ID=, tg_label_flag=0
May  2 19:15:03.972: //-1/xxxxxxxxxxxx/VTSP:(50/0/9):-1:-1:-1/vtsp_do_call_setup_ind: 
   Calling Number=8998, TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed
   CLIR=FALSE, CLID Transparent=FALSE, Null Originating Calling Number=FALSE, Calling Translated=FALSE
May  2 19:15:03.972: //-1/6D63AF058016/VTSP:(50/0/9):-1:-1:-1/vtsp_do_normal_call_setup_ind:
May  2 19:15:03.972: //-1/6D63AF058016/VTSP:(50/0/9):-1:-1:-1/vtsp_timer: 
   Timer Start Time=2436434, Timer Value=180000(ms)
May  2 19:15:03.972: //-1/6D63AF058016/VTSP:(50/0/9):-1:-1:-1/vtsp_do_normal_call_setup_ind: 
   IC State Machine (ICSM) Added
May  2 19:15:03.972: //-1/6D63AF058016/VTSP:(50/0/9):-1:-1:-1/vtsp_insert_cdb:
May  2 19:15:03.972: //-1/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_opened_cb:
May  2 19:15:03.972: //-1/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_process_event: 
   [state:S_SETUP_IND_PEND, event:E_VTSP_DSM_OPEN_SUCCESS]
May  2 19:15:03.972: //-1/6D63AF058016/VTSP:(50/0/9):-1:0:65/act_setup_ind_pend_success:
May  2 19:15:03.972: //-1/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_realloc_cdb: 
   CDB=0x2A64EE18
May  2 19:15:03.972: //-1/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_indicate_call:
May  2 19:15:03.972: //-1/6D63AF058016/CCAPI/cc_api_display_ie_subfields:
   cc_api_call_setup_ind_common:
   cisco-username=
   ----- ccCallInfo IE subfields -----
   cisco-ani=8998
   cisco-anitype=0
   cisco-aniplan=0
   cisco-anipi=0
   cisco-anisi=0
   dest=
   cisco-desttype=0
   cisco-destplan=0
   cisco-rdie=FFFFFFFF
   cisco-rdn=
   cisco-rdntype=0
   cisco-rdnplan=0
   cisco-rdnpi=0
   cisco-rdnsi=0
   cisco-redirectreason=0   fwd_final_type =0
   final_redirectNumber =
   hunt_group_timeout =0

May  2 19:15:03.972: //-1/6D63AF058016/CCAPI/cc_api_call_setup_ind_common:
   Interface=0x31A9C0FC, Call Info(
   Calling Number=8998,(Calling Name=)(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
   Called Number=(TON=Unknown, NPI=Unknown),
   Calling Translated=FALSE, Subscriber Type Str=RegularLine, FinalDestinationFlag=FALSE,
   Incoming Dial-peer=20009, Progress Indication=ORIGINATING SIDE IS NON ISDN(3), Calling IE Present=TRUE,
   Source Trkgrp Route Label=, Target Trkgrp Route Label=, CLID Transparent=FALSE), Call Id=-1
May  2 19:15:03.972: //-1/6D63AF058016/CCAPI/ccCheckClipClir:
   In: Calling Number=8998(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
May  2 19:15:03.972: //-1/6D63AF058016/CCAPI/ccCheckClipClir:
   Out: Calling Number=8998(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
May  2 19:15:03.972: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
  
May  2 19:15:03.972: :cc_get_feature_vsa malloc success
May  2 19:15:03.972: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
  
May  2 19:15:03.972:  cc_get_feature_vsa count is 1
May  2 19:15:03.972: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
  
May  2 19:15:03.972: :FEATURE_VSA attributes are: feature_name:0,feature_time:711176472,feature_id:9
May  2 19:15:03.972: //9/6D63AF058016/CCAPI/cc_api_call_setup_ind_common:
   Set Up Event Sent;
   Call Info(Calling Number=8998(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
   Called Number=(TON=Unknown, NPI=Unknown))
May  2 19:15:03.972: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_insert_cdb:
May  2 19:15:03.972: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_timer: 
   Timer Start Time=2436434, Timer Value=180000(ms)
May  2 19:15:03.972: //9/6D63AF058016/CCAPI/cc_process_call_setup_ind:
   Event=0x2B4E96B0
May  2 19:15:03.972: //9/6D63AF058016/CCAPI/ccCallSetContext:
   Context=0x304C35A8
May  2 19:15:03.976: //9/6D63AF058016/CCAPI/cc_process_call_setup_ind:
   >>>>CCAPI handed cid 9 with tag 20009 to app "_ManagedAppProcess_Default"
May  2 19:15:03.976: //9/6D63AF058016/CCAPI/ccCallSetupAck:
   Call Id=9
May  2 19:15:03.976: //9/6D63AF058016/CCAPI/cc_api_set_transfer_info:
   Transfer Number=, Transfer Reason=0x0
May  2 19:15:03.976: //9/6D63AF058016/CCAPI/ccGenerateToneInfo:
   Stop Tone On Digit=TRUE, Tone=Dial Tone,
   Tone Direction=Network, Params=0x0, Call Id=9
May  2 19:15:03.976: //9/6D63AF058016/CCAPI/ccSetDigitTimeouts:
   Initial Digit Timeout=-1000(ms), Inter Digit Timeout=-1000(ms)
May  2 19:15:03.976: //9/6D63AF058016/CCAPI/ccSetDigitTimeouts:
   Call Entry(Inter Digit Timeout=10000(ms), Initial Digit Timeout=10000(ms))
May  2 19:15:03.976: //9/6D63AF058016/CCAPI/ccCallReportDigits:
   (callID=0x9, digit_event=0x1, enable=TRUE, consume=FALSE)
May  2 19:15:03.976: //9/6D63AF058016/CCAPI/ccCallReportDigits:
   Enabled=TRUE, Call Id=9
May  2 19:15:03.976: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_report_digit_control:
May  2 19:15:03.976: //9/6D63AF058016/CCAPI/cc_api_call_report_digits_done:
   (vdbPtr=0x31A9C0FC, callID=0x9, disp=0, digit_event=0x1, enable=TRUE, consume=FALSE)
May  2 19:15:03.976: //9/6D63AF058016/CCAPI/cc_api_call_report_digits_done:
   Enabled=TRUE, Disposition=0x0, Interface=0x31A9C0FC, Call Id=9
May  2 19:15:03.976: //9/6D63AF058016/CCAPI/cc_api_call_report_digits_done:
   Call Entry(Initial Digit Timeout=15000(ms), Inter Digit Timeout=5000(ms))
May  2 19:15:03.976: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_report_digit_control: 
   Digit Reporting=TRUE
May  2 19:15:03.976: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_process_event: 
   [state:S_SETUP_INDICATED, event:E_CC_SETUP_ACK]
May  2 19:15:03.976: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/act_setup_ind_ack: 
   Fax Relay=TRUE, Dial Tone=TRUE, Digit Collect=TRUE, Overlap=FALSE, DID=FALSE
May  2 19:15:03.976: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_timer_stop: 
   Timer Stop Time=2436434
May  2 19:15:03.976: htsp_process_event: [50/0/9.1, EFXS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]efxs_check_auto_call
May  2 19:15:04.704: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_begin_cb:
May  2 19:15:04.708: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_begin_cb: 
   Begin Digit=9
May  2 19:15:04.708: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_begin_cb: 
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=TRUE
May  2 19:15:04.708: //9/6D63AF058016/CCAPI/cc_api_call_digit_begin:
   Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
   Source Call Id=9, Digit=9, DigitBeginFlags=0x0,
   Rtp Timestamp=0x11E608, Rtp Expiration=0x0
May  2 19:15:04.708: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_end_cb:
May  2 19:15:04.708: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_timer_stop: 
   Timer Stop Time=2436508
May  2 19:15:04.708: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_end_cb: 
   End Digit=9
May  2 19:15:04.708: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_end_cb: 
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=TRUE
May  2 19:15:04.708: //9/6D63AF058016/CCAPI/cc_api_call_digit_end:
   Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
   Source Call Id=9, Digit=9, Duration=100,
   Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
May  2 19:15:04.708: //9/6D63AF058016/CCAPI/cc_api_call_digit_end:
   Call Entry(Handoff Depth=0)
May  2 19:15:04.708: htsp_digit_ready(50/0/9.1): digit = 9
May  2 19:15:04.708: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_begin_cb:
May  2 19:15:04.708: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_begin_cb: 
   Begin Digit=1
May  2 19:15:04.708: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_begin_cb: 
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=TRUE
May  2 19:15:04.708: //9/6D63AF058016/CCAPI/cc_api_call_digit_begin:
   Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
   Source Call Id=9, Digit=1, DigitBeginFlags=0x0,
   Rtp Timestamp=0x126308, Rtp Expiration=0x0
May  2 19:15:04.708: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_end_cb:
May  2 19:15:04.708: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_timer_stop: 
   Timer Stop Time=2436508
May  2 19:15:04.708: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_end_cb: 
   End Digit=1
May  2 19:15:04.708: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_end_cb: 
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=TRUE
May  2 19:15:04.708: //9/6D63AF058016/CCAPI/cc_api_call_digit_end:
   Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
   Source Call Id=9, Digit=1, Duration=100,
   Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
May  2 19:15:04.708: //9/6D63AF058016/CCAPI/cc_api_call_digit_end:
   Call Entry(Handoff Depth=0)
May  2 19:15:04.708: htsp_digit_ready(50/0/9.1): digit = 1
May  2 19:15:04.960: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_begin_cb:
May  2 19:15:04.960: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_begin_cb: 
   Begin Digit=2
May  2 19:15:04.960: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_begin_cb: 
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=TRUE
May  2 19:15:04.960: //9/6D63AF058016/CCAPI/cc_api_call_digit_begin:
   Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
   Source Call Id=9, Digit=2, DigitBeginFlags=0x0,
   Rtp Timestamp=0x12E008, Rtp Expiration=0x0
May  2 19:15:04.960: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_end_cb:
May  2 19:15:04.960: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_timer_stop: 
   Timer Stop Time=2436533
May  2 19:15:04.960: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_end_cb: 
   End Digit=2
May  2 19:15:04.960: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_end_cb: 
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=TRUE
May  2 19:15:04.960: //9/6D63AF058016/CCAPI/cc_api_call_digit_end:
   Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
   Source Call Id=9, Digit=2, Duration=100,
   Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
May  2 19:15:04.960: //9/6D63AF058016/CCAPI/cc_api_call_digit_end:
   Call Entry(Handoff Depth=0)
May  2 19:15:04.960: htsp_digit_ready(50/0/9.1): digit = 2
May  2 19:15:04.960: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_begin_cb:
May  2 19:15:04.960: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_begin_cb: 
   Begin Digit=7
May  2 19:15:04.960: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_begin_cb: 
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=TRUE
May  2 19:15:04.960: //9/6D63AF058016/CCAPI/cc_api_call_digit_begin:
   Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
   Source Call Id=9, Digit=7, DigitBeginFlags=0x0,
   Rtp Timestamp=0x135D08, Rtp Expiration=0x0
May  2 19:15:04.960: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_end_cb:
May  2 19:15:04.960: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_timer_stop: 
   Timer Stop Time=2436533
May  2 19:15:04.960: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_end_cb: 
   End Digit=7
May  2 19:15:04.960: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_end_cb: 
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=TRUE
May  2 19:15:04.960: //9/6D63AF058016/CCAPI/cc_api_call_digit_end:
   Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
   Source Call Id=9, Digit=7, Duration=100,
   Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
May  2 19:15:04.960: //9/6D63AF058016/CCAPI/cc_api_call_digit_end:
   Call Entry(Handoff Depth=0)
May  2 19:15:04.960: htsp_digit_ready(50/0/9.1): digit = 7
May  2 19:15:05.412: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_begin_cb:
May  2 19:15:05.412: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_begin_cb: 
   Begin Digit=7
May  2 19:15:05.412: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_begin_cb: 
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=TRUE
May  2 19:15:05.412: //9/6D63AF058016/CCAPI/cc_api_call_digit_begin:
   Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
   Source Call Id=9, Digit=7, DigitBeginFlags=0x0,
   Rtp Timestamp=0x13DA08, Rtp Expiration=0x0
May  2 19:15:05.412: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_end_cb:
May  2 19:15:05.412: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_timer_stop: 
   Timer Stop Time=2436578
May  2 19:15:05.412: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_end_cb: 
   End Digit=7
May  2 19:15:05.412: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_end_cb: 
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=TRUE
May  2 19:15:05.412: //9/6D63AF058016/CCAPI/cc_api_call_digit_end:
   Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
   Source Call Id=9, Digit=7, Duration=100,
   Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
May  2 19:15:05.412: //9/6D63AF058016/CCAPI/cc_api_call_digit_end:
   Call Entry(Handoff Depth=0)
May  2 19:15:05.412: htsp_digit_ready(50/0/9.1): digit = 7
May  2 19:15:05.412: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_begin_cb:
May  2 19:15:05.412: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_begin_cb: 
   Begin Digit=8
May  2 19:15:05.412: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_begin_cb: 
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=TRUE
May  2 19:15:05.412: //9/6D63AF058016/CCAPI/cc_api_call_digit_begin:
   Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
   Source Call Id=9, Digit=8, DigitBeginFlags=0x0,
   Rtp Timestamp=0x145708, Rtp Expiration=0x0
May  2 19:15:05.412: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_end_cb:
May  2 19:15:05.412: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_timer_stop: 
   Timer Stop Time=2436578
May  2 19:15:05.412: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_end_cb: 
   End Digit=8
May  2 19:15:05.412: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_end_cb: 
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=TRUE
May  2 19:15:05.412: //9/6D63AF058016/CCAPI/cc_api_call_digit_end:
   Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
   Source Call Id=9, Digit=8, Duration=100,
   Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
May  2 19:15:05.412: //9/6D63AF058016/CCAPI/cc_api_call_digit_end:
   Call Entry(Handoff Depth=0)
May  2 19:15:05.412: htsp_digit_ready(50/0/9.1): digit = 8
May  2 19:15:05.416: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_begin_cb:
May  2 19:15:05.416: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_begin_cb: 
   Begin Digit=2
May  2 19:15:05.416: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_begin_cb: 
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=TRUE
May  2 19:15:05.416: //9/6D63AF058016/CCAPI/cc_api_call_digit_begin:
   Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
   Source Call Id=9, Digit=2, DigitBeginFlags=0x0,
   Rtp Timestamp=0x14D408, Rtp Expiration=0x0
May  2 19:15:05.416: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_end_cb:
May  2 19:15:05.416: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_timer_stop: 
   Timer Stop Time=2436578
May  2 19:15:05.416: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_end_cb: 
   End Digit=2
May  2 19:15:05.416: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_end_cb: 
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=TRUE
May  2 19:15:05.416: //9/6D63AF058016/CCAPI/cc_api_call_digit_end:
   Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
   Source Call Id=9, Digit=2, Duration=100,
   Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
May  2 19:15:05.416: //9/6D63AF058016/CCAPI/cc_api_call_digit_end:
   Call Entry(Handoff Depth=0)
May  2 19:15:05.416: htsp_digit_ready(50/0/9.1): digit = 2
May  2 19:15:05.416: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_begin_cb:
May  2 19:15:05.416: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_begin_cb: 
   Begin Digit=9
May  2 19:15:05.416: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_begin_cb: 
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=TRUE
May  2 19:15:05.416: //9/6D63AF058016/CCAPI/cc_api_call_digit_begin:
   Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
   Source Call Id=9, Digit=9, DigitBeginFlags=0x0,
   Rtp Timestamp=0x155108, Rtp Expiration=0x0
May  2 19:15:05.416: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_end_cb:
May  2 19:15:05.416: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_timer_stop: 
   Timer Stop Time=2436578
May  2 19:15:05.416: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_end_cb: 
   End Digit=9
May  2 19:15:05.416: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_end_cb: 
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=TRUE
May  2 19:15:05.416: //9/6D63AF058016/CCAPI/cc_api_call_digit_end:
   Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
   Source Call Id=9, Digit=9, Duration=100,
   Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
May  2 19:15:05.416: //9/6D63AF058016/CCAPI/cc_api_call_digit_end:
   Call Entry(Handoff Depth=0)
May  2 19:15:05.416: htsp_digit_ready(50/0/9.1): digit = 9
May  2 19:15:05.668: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_begin_cb:
May  2 19:15:05.668: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_begin_cb: 
   Begin Digit=4
May  2 19:15:05.668: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_begin_cb: 
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=TRUE
May  2 19:15:05.668: //9/6D63AF058016/CCAPI/cc_api_call_digit_begin:
   Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
   Source Call Id=9, Digit=4, DigitBeginFlags=0x0,
   Rtp Timestamp=0x15CE08, Rtp Expiration=0x0
May  2 19:15:05.668: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_end_cb:
May  2 19:15:05.668: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_timer_stop: 
   Timer Stop Time=2436604
May  2 19:15:05.668: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_end_cb: 
   End Digit=4
May  2 19:15:05.668: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_dsm_digit_end_cb: 
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=TRUE
May  2 19:15:05.668: //9/6D63AF058016/CCAPI/cc_api_call_digit_end:
   Destination Interface=0x0, Destination Mask=0x3, Destination Call Id=-1,
   Source Call Id=9, Digit=4, Duration=100,
   Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
May  2 19:15:05.668: //9/6D63AF058016/CCAPI/cc_api_call_digit_end:
   Call Entry(Handoff Depth=0)
May  2 19:15:05.668: htsp_digit_ready(50/0/9.1): digit = 4
May  2 19:15:10.668: //9/6D63AF058016/CCAPI/cc_handle_inter_digit_timer:
   Generate inter-digit timeout CC_EV_CALL_DIGIT_END event
May  2 19:15:10.668: //9/6D63AF058016/CCAPI/ccCallReportDigits:
   (callID=0x9, digit_event=0x0, enable=FALSE, consume=FALSE)
May  2 19:15:10.668: //9/6D63AF058016/CCAPI/ccCallReportDigits:
   Enabled=TRUE, Call Id=9
May  2 19:15:10.668: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_report_digit_control:
May  2 19:15:10.668: //9/6D63AF058016/CCAPI/cc_api_call_report_digits_done:
   (vdbPtr=0x31A9C0FC, callID=0x9, disp=0, digit_event=0x0, enable=FALSE, consume=FALSE)
May  2 19:15:10.668: //9/6D63AF058016/CCAPI/cc_api_call_report_digits_done:
   Enabled=TRUE, Disposition=0x0, Interface=0x31A9C0FC, Call Id=9
May  2 19:15:10.668: //9/6D63AF058016/CCAPI/cc_api_call_report_digits_done:
   Call Entry(Initial Digit Timeout=15000(ms), Inter Digit Timeout=5000(ms))
May  2 19:15:10.668: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_report_digit_control: 
   Digit Reporting=FALSE
May  2 19:15:10.668: //9/6D63AF058016/CCAPI/ccCallProceeding:
   Progress Indication=NULL(0)
May  2 19:15:10.668: //9/6D63AF058016/CCAPI/ccCallSetupRequest:
   Destination=, Calling IE Present=TRUE, Mode=0,
   Outgoing Dial-peer=10, Params=0x304C4AB8, Progress Indication=ORIGINATING SIDE IS NON ISDN(3)
May  2 19:15:10.668: //9/6D63AF058016/CCAPI/cc_fill_tg_params:
   Not a cic call
May  2 19:15:10.668: //9/6D63AF058016/CCAPI/ccCallSetupRequest:
   Trunk Group Select Interface Success;
   Interface=0x2B541470, Selected Interface=1, Selected DSL=-1
May  2 19:15:10.668: //9/6D63AF058016/CCAPI/ccCheckClipClir:
   In: Calling Number=8998(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
May  2 19:15:10.668: //9/6D63AF058016/CCAPI/ccCheckClipClir:
   Out: Calling Number=8998(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
May  2 19:15:10.668: //9/6D63AF058016/CCAPI/ccCallSetupRequest:
   Destination Pattern=9T, Called Number=912778294, Digit Strip=TRUE
May  2 19:15:10.668: //9/6D63AF058016/CCAPI/ccCallSetupRequest:
   Calling Number=8998(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
   Called Number=912778294(TON=Unknown, NPI=Unknown),
   Redirect Number=, Display Info=Guest4
   Account Number=, Final Destination Flag=FALSE,
   Guid=6D63AF05-B293-11E2-8016-9FBC04AB56B6, Outgoing Dial-peer=10
May  2 19:15:10.668: //9/6D63AF058016/CCAPI/cc_api_display_ie_subfields:
   ccCallSetupRequest:
   cisco-username=
   ----- ccCallInfo IE subfields -----
   cisco-ani=8998
   cisco-anitype=0
   cisco-aniplan=0
   cisco-anipi=0
   cisco-anisi=0
   dest=912778294
   cisco-desttype=0
   cisco-destplan=0
   cisco-rdie=FFFFFFFF
   cisco-rdn=
   cisco-rdntype=0
   cisco-rdnplan=0
   cisco-rdnpi=0
   cisco-rdnsi=0
   cisco-redirectreason=0   fwd_final_type =0
   final_redirectNumber =
   hunt_group_timeout =0

May  2 19:15:10.668: //9/6D63AF058016/CCAPI/ccIFCallSetupRequestPrivate:
   Interface=0x2B541470, Interface Type=6, Destination=, Mode=0x0,
   Call Params(Calling Number=8998,(Calling Name=Guest4)(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
   Called Number=912778294(TON=Unknown, NPI=Unknown), Calling Translated=FALSE,
   Subscriber Type Str=RegularLine, FinalDestinationFlag=FALSE, Outgoing Dial-peer=10, Call Count On=FALSE,
   Source Trkgrp Route Label=, Target Trkgrp Route Label=POTS, tg_label_flag=2, Application Call Id=)
May  2 19:15:10.668: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
  
May  2 19:15:10.668: :cc_get_feature_vsa malloc success
May  2 19:15:10.668: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
  
May  2 19:15:10.668:  cc_get_feature_vsa count is 2
May  2 19:15:10.668: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
  
May  2 19:15:10.668: :FEATURE_VSA attributes are: feature_name:0,feature_time:711176248,feature_id:10
May  2 19:15:10.668: //-1/xxxxxxxxxxxx/VTSP:(0/0/0):-1:-1:-1/vtsp_allocate_cdb: 
   CDB=0x2A64EB40
May  2 19:15:10.668: //-1/xxxxxxxxxxxx/VTSP:(0/0/0):-1:-1:-1/vtsp_insert_cdb:
May  2 19:15:10.668: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_spi_event_handler: 
   Event Category=1, Event=176
May  2 19:15:10.668: //10/6D63AF058016/CCAPI/ccIFCallSetupRequestPrivate:
   SPI Call Setup Request Is Success; Interface Type=6, FlowMode=1
May  2 19:15:10.668: //9/6D63AF058016/CCAPI/ccCallSetupRequest:
   Trunk Group Call Setting;
   Call Entry(Retry Count=0, Voice Class Cause Code=0)
May  2 19:15:10.668: //10/6D63AF058016/CCAPI/ccCallSetContext:
   Context=0x304C4A68
May  2 19:15:10.668: //9/6D63AF058016/CCAPI/ccSaveDialpeerTag:
   Outgoing Dial-peer=10
May  2 19:15:10.672: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_process_event: 
   [state:S_DIGIT_COLLECT, event:E_CC_PROCEEDING]
May  2 19:15:10.672: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/act_dcollect_proc:
May  2 19:15:10.672: //-1/xxxxxxxxxxxx/VTSP:(0/0/0):-1:-1:-1/vtsp_process_event: 
   [state:INVALID STATE MACHINE, event:E_CC_SETUP_REQ]
May  2 19:15:10.672: //10/xxxxxxxxxxxx/VTSP:(0/0/0):-1:-1:-1/vtsp_og_call_req: 
   Target Trkgrp Route Label=POTS
May  2 19:15:10.672: //9/6D63AF058016/CCAPI/cc_api_modify_tgt_cid_call_active_record:
   Target Trkgrp Route Label=POTS, tg_label_flag=TRUE, Call Id=0x9
May  2 19:15:10.672: htsp_timer_stop3
May  2 19:15:10.672: //10/6D63AF058016/VTSP:(0/0/0):-1:-1:-1/vtsp_og_call_req: 
   Echo Cancel=TRUE, Gain Control=0
   Auto Gain Control=FALSE, Dual Tone Detect Mask=0x0, Seq Tone Detect=FALSE
May  2 19:15:10.672: //10/6D63AF058016/VTSP:(0/0/0):-1:-1:-1/vtsp_do_call_setup_req:
May  2 19:15:10.672: htsp_process_event: [50/0/9.1, EFXS_OFFHOOK, E_HTSP_PROCEEDING]efxs_offhook_proceeding
May  2 19:15:10.672: [50/0/9.1] set signal state = 0x8 timestamp = 0
May  2 19:15:10.672: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_dsm_opened_cb:
May  2 19:15:10.672: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_process_event: 
   [state:S_SETUP_REQ_PEND, event:E_VTSP_DSM_OPEN_SUCCESS]
May  2 19:15:10.672: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/act_setup_req_pend_succ:
May  2 19:15:10.672: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_request_call: 
   Mode=0, Peer=10
May  2 19:15:10.672: digit_strip:1, pcn:912778294, poa:9T
May  2 19:15:10.672: pcn:12778294, poa:T
May  2 19:15:10.672: Final pcn:12778294, poa:T, dial_string:12778294
May  2 19:15:10.672: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_create_call_active_on_setup_req: 
   Target Trkgrp Route Label=POTS
May  2 19:15:10.672: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_create_call_active_on_setup_req: 
   Source Trkgrp Route Label=htsp_setup_req
May  2 19:15:10.672: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_request_call: 
   Progress Indication=3, Info Trans Capability=0
   Calling Number=8998, TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed
   Called Number=912778294, TON=Unknown, NPI=Unknown
May  2 19:15:10.672: htsp_process_event: [0/0/0, FXOLS_ONHOOK, E_HTSP_SETUP_REQ]fxols_onhook_setup
May  2 19:15:10.672: [0/0/0] set signal state = 0xC timestamp = 0
May  2 19:15:10.672: htsp_timer - 1300 msec
May  2 19:15:10.672: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_process_event: 
   [state:S_SETUP_REQUEST, event:E_TSP_PROCEEDING]
May  2 19:15:10.672: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/act_setup_pend_proceeding:
May  2 19:15:10.672: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_timer: 
   Timer Start Time=2437104, Timer Value=25000(ms)
May  2 19:15:10.672: //10/6D63AF058016/CCAPI/cc_api_call_proceeding:
   Interface=0x2B541470, Progress Indication=NULL(0)
May  2 19:15:10.672: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/act_setup_pend_proceeding: 
   Peer=10, Progress Indication=0, Return Code=2
May  2 19:15:10.676: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_dsm_opened_cb:
May  2 19:15:10.676: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_process_event: 
   [state:S_NULL, event:E_VTSP_DSM_OPEN_SUCCESS]
May  2 19:15:10.676: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/act_setup_req_wait_pend_success: 
   Event=75
May  2 19:15:10.676: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop: 
   Timer Stop Time=2437104
May  2 19:15:10.928: htsp_process_event: [0/0/0, FXOLS_WAIT_DIAL_TONE, E_DSP_SIG_1100]fxols_power_denial_detected
May  2 19:15:10.928: htsp_timer2 - 1000 msec
May  2 19:15:10.928: htsp_timer_stop
May  2 19:15:11.928: htsp_process_event: [0/0/0, FXOLS_WAIT_DIAL_TONE, E_HTSP_EVENT_TIMER2]fxols_power_den_disc
May  2 19:15:11.928: htsp_timer_stop
May  2 19:15:11.928: htsp_timer_stop2
May  2 19:15:11.928: [0/0/0] set signal state = 0x4 timestamp = 0
May  2 19:15:11.928: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_process_event: 
   [state:S_SETUP_REQ_PROC, event:E_TSP_DISCONNECT_IND]
May  2 19:15:11.928: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/act_setup_pend_release_ind: 
   Cause Value=34
May  2 19:15:11.928: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_ring_noan_timer_stop: 
   Timer Stop Time=2437230
May  2 19:15:11.928: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_cc_call_disconnected:
May  2 19:15:11.928: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_cc_call_disconnected: 
   Cause Value=34
May  2 19:15:11.928: //10/6D63AF058016/CCAPI/cc_api_call_disconnected:
   Cause Value=34, Interface=0x2B541470, Call Id=10
May  2 19:15:11.928: //10/6D63AF058016/CCAPI/cc_api_call_disconnected:
   Call Entry(Responsed=TRUE, Cause Value=34, Retry Count=0)
May  2 19:15:11.928: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_set_release_source: 
   Release Direction=PSTN, Release Source=Called Party-PSTN
May  2 19:15:11.928: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/act_setup_pend_release_ind: 
   Peer=10
May  2 19:15:11.928: //9/6D63AF058016/CCAPI/ccCallReleaseResources:
   release reserved xcoding resource.
May  2 19:15:11.928: //10/6D63AF058016/CCAPI/ccCallSetAAA_Accounting:
   Accounting=0, Call Id=10
May  2 19:15:11.928: //10/6D63AF058016/CCAPI/ccCallDisconnect:
   Cause Value=34, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=34)
May  2 19:15:11.928: //10/6D63AF058016/CCAPI/ccCallDisconnect:
   Cause Value=34, Call Entry(Responsed=TRUE, Cause Value=34)
May  2 19:15:11.928: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_call_disconnect: 
   [Out Of Service]-Tone Played In Direction [Both]
May  2 19:15:11.928: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_process_event: 
   [state:S_WAIT_HOST_DISC, event:E_CC_DISCONNECT]
May  2 19:15:11.928: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/act_host_disc_cleanup: 
   dsm_indicate_error=0, short_cleardown_timeout=0, Mode=0
May  2 19:15:11.928: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/act_host_disc_cleanup: 
   Exit State=16
May  2 19:15:11.928: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_dsm_get_levels_done_cb:
May  2 19:15:11.928: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_process_event: 
   [state:S_WAIT_STATS, event:E_VTSP_DSM_STATS_COMPLETE]
May  2 19:15:11.928: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/act_dsm_dsp_stats_complete:
May  2 19:15:11.928: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_timer: 
   Timer Start Time=2437230, Timer Value=60000(ms)
May  2 19:15:11.928: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_process_event: 
   [state:S_WAIT_RELEASE, event:E_VTSP_DSM_STATS_COMPLETE]
May  2 19:15:11.928: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_process_event: 
   Unexpected EVENT [E_VTSP_DSM_STATS_COMPLETE] Received For STATE [S_WAIT_RELEASE];
   Previous STATE [0.16 ]
May  2 19:15:11.928: htsp_process_event: [0/0/0, FXOLS_ONHOOK, E_HTSP_RELEASE_REQ]fxols_onhook_release
May  2 19:15:11.928: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_process_event: 
   [state:S_WAIT_RELEASE, event:E_TSP_DISCONNECT_CONF]
May  2 19:15:11.928: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/act_wrelease_release:
May  2 19:15:11.928: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_play_busy_timer_stop: 
   Timer Stop Time=2437230
May  2 19:15:11.928: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop: 
   Timer Stop Time=2437230
May  2 19:15:11.928: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_do_call_history:
May  2 19:15:11.928: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_do_call_history: 
   Coder Rate=-1
May  2 19:15:11.932: //10/6D63AF058016/VTSP:(0/0/0):-1:1:1/vtsp_is_valid_dsm_handle: 
   DMGR=0x2AD73208, VTSP CDB=0x2A64EB40
May  2 19:15:11.932: //10/6D63AF058016/VTSP:(0/0/0):-1:-1:-1/vtsp_dsm_closed_cb:
May  2 19:15:11.932: //10/6D63AF058016/VTSP:(0/0/0):-1:-1:-1/vtsp_process_event: 
   [state:S_CLOSE_DSPRM, event:E_VTSP_DSM_CLOSE_COMPLETE]
May  2 19:15:11.932: //10/6D63AF058016/VTSP:(0/0/0):-1:-1:-1/act_terminate:
May  2 19:15:11.932: //10/6D63AF058016/VTSP:(0/0/0):-1:-1:-1/vtsp_timer_stop: 
   Timer Stop Time=2437230
May  2 19:15:11.932: //10/6D63AF058016/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x2B541470, Tag=0x0, Call Id=10,
   Call Entry(Disconnect Cause=34, Voice Class Cause Code=0, Retry Count=0)
May  2 19:15:11.932: //10/6D63AF058016/CCAPI/cc_api_call_disconnect_done:
   tg for this call is POTS success/fail is 0
May  2 19:15:11.932: //10/6D63AF058016/CCAPI/cc_api_call_disconnect_done:
   Call Disconnect Event Sent
May  2 19:15:11.932: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
  
May  2 19:15:11.932: :cc_free_feature_vsa freeing 2A63B030
May  2 19:15:11.932: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
  
May  2 19:15:11.932:  vsacount in free is 1
May  2 19:15:11.932: //-1/6D63AF058016/VTSP:(0/0/0):-1:-1:-1/vtsp_free_cdb: 
   CDB=0x2A64EB40
May  2 19:15:11.932: //9/6D63AF058016/CCAPI/ccCallDisconnect:
   Cause Value=34, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
May  2 19:15:11.932: //9/6D63AF058016/CCAPI/ccCallDisconnect:
   Cause Value=34, Call Entry(Responsed=TRUE, Cause Value=34)
May  2 19:15:11.932: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_call_disconnect: 
   [Out Of Service]-Tone Played In Direction [Both]
May  2 19:15:11.932: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_process_event: 
   [state:S_PROCEEDING, event:E_CC_DISCONNECT]
May  2 19:15:11.932: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/act_pre_con_disconnect: 
   Cause Value=34, Hairpin=FALSE
May  2 19:15:11.932: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_timer_stop: 
   Timer Stop Time=2437230
May  2 19:15:11.932: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_ring_noan_timer_stop: 
   Timer Stop Time=2437230
May  2 19:15:11.932: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/act_pre_con_disconnect: 
   [Out Of Service]-Tone Played In Direction [Network]
May  2 19:15:11.932: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_timer_stop: 
   Timer Stop Time=2437230
May  2 19:15:11.932: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_play_busy_timer_start: 
   Timer Start Time=2437230, Busy Timer Value=30(ms)
May  2 19:15:11.932: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/act_pre_con_disconnect: 
   Tone=Out Of Service, Tone Timeout=30(s), Progress Indication Sent=0
May  2 19:15:23.268: htsp_process_event: [50/0/9.1, EFXS_OFFHOOK, E_DSP_SIG_0100]efxs_offhook_onhook
May  2 19:15:23.268: htsp_timer - 10 msec
May  2 19:15:23.280: htsp_process_event: [50/0/9.1, EFXS_OFFHOOK, E_HTSP_EVENT_TIMER]efxs_offhook_timer
May  2 19:15:23.280: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_process_event: 
   [state:S_WAIT_RELEASE_NC, event:E_TSP_DISCONNECT_IND]
May  2 19:15:23.280: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/act_pre_con_disc_rel:
May  2 19:15:23.280: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/act_pre_con_disc_rel: 
   Cause Value=34
May  2 19:15:23.280: htsp_process_event: [50/0/9.1, EFXS_ONHOOK, E_HTSP_RELEASE_REQ]efxs_onhook_release
May  2 19:15:23.280: htsp_timer_stop
May  2 19:15:23.280: [50/0/9.1] set signal state = 0x4 timestamp = 0
May  2 19:15:23.280: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_process_event: 
   [state:S_WAIT_RELEASE_RESP, event:E_TSP_DISCONNECT_CONF]
May  2 19:15:23.280: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/act_wrelease_release:
May  2 19:15:23.280: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_play_busy_timer_stop: 
   Timer Stop Time=2438365
May  2 19:15:23.280: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_timer_stop: 
   Timer Stop Time=2438365
May  2 19:15:23.280: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_do_call_history:
May  2 19:15:23.280: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_do_call_history: 
   Coder Rate=-1
May  2 19:15:23.280: //9/6D63AF058016/VTSP:(50/0/9):-1:0:65/vtsp_is_valid_dsm_handle: 
   DMGR=0x2AD764A4, VTSP CDB=0x2A64EE18
May  2 19:15:23.280: //9/6D63AF058016/VTSP:(50/0/9):-1:-1:-1/vtsp_dsm_closed_cb:
May  2 19:15:23.280: //9/6D63AF058016/VTSP:(50/0/9):-1:-1:-1/vtsp_process_event: 
   [state:S_CLOSE_DSPRM, event:E_VTSP_DSM_CLOSE_COMPLETE]
May  2 19:15:23.280: //9/6D63AF058016/VTSP:(50/0/9):-1:-1:-1/act_terminate:
May  2 19:15:23.280: //9/6D63AF058016/VTSP:(50/0/9):-1:-1:-1/vtsp_timer_stop: 
   Timer Stop Time=2438365
May  2 19:15:23.280: //9/6D63AF058016/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x31A9C0FC, Tag=0x0, Call Id=9,
   Call Entry(Disconnect Cause=34, Voice Class Cause Code=0, Retry Count=0)
May  2 19:15:23.280: //9/6D63AF058016/CCAPI/cc_api_call_disconnect_done:
   Call Disconnect Event Sent
May  2 19:15:23.280: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
  
May  2 19:15:23.280: :cc_free_feature_vsa freeing 2A63B110
May  2 19:15:23.280: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
  
May  2 19:15:23.280:  vsacount in free is 0
May  2 19:15:23.280: //-1/6D63AF058016/VTSP:(50/0/9):-1:-1:-1/vtsp_free_cdb: 
   CDB=0x2A64EE18
Carlyle_VGW#
Carlyle_VGW#
Carlyle_VGW#
Carlyle_VGW#

[Kevin Monteiro]

Hi Joan,

This is a 100% Service-provider issue. There is a issue with the cabling from the SP.

   Call Entry(Disconnect Cause=34, Voice Class Cause Code=0, Retry Count=0)

The cause code  34 means = no circuit (34).

Contact your SP, they should fix the issue.

-Regards,

Kevin