CME 2911 DEBUG VOICE CCAPI INOUT ANI=EMPTY CODE ERROR=28

[fdamian01]

hi
  I'm setting the integration of a Cisco 2911 and Avaya, Cisco calls to Avaya works

Incoming calls Avaya cisco not working

Stage:

Avaya extensions were created 4880,4881,4882
PSTN DID number 12345 reaches an extension Avaya 4889
89901 group receives a call distributes extensions in 4880,4881,4882

Sequence: 

PSTN-AVAYA-CISCO

I have FXO ports on the Cisco and Avaya FXS

I have the following configuration

voice translation-rule 2   (89901 group convert it to the next extension of the operator (800)
rule 1 /89901/ /800/

voice translation-profile DID2
translate called 2

configure my dial-peer with the corresponding ports

dial-peer voice 503 pots
description DIDs Avaya to Cisco Unified Communicatios Manager Express
translation-profile incoming DID2
destination-pattern 800
incoming called-number 800
direct-inward-dial
port 0/1/3
!
dial-peer voice 507 pots
description DIDs Avaya to Cisco Unified Communicatios Manager Express
translation-profile incoming DID2
destination-pattern 800
incoming called-number 800
direct-inward-dial
port 0/2/3

My logic is well ??

my setup right?

http://www.cisco.com/c/en/us/td/docs/ios/voice/monitor/configuration/guide/12_4/vt_12_4_book/vt_ccodes_debug.html

which means exactly the error 28?

It means that the group does not reach me ??

apply debug voice ccapi inout

the source is empty

cc_api_call_setup_ind_common:
cisco-username=
----- ccCallInfo IE subfields -----
cisco-ani=
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

104319: *Jan 25 20:41:11.879 Mexico: //-1/188F7F4684E0/CCAPI/cc_api_call_setup_ind_common:
Interface=0x223BF8D0, Call Info(
Calling Number=,(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=TRUE,
Incoming Dial-peer=507, Progress Indication=ORIGINATING SIDE IS NON ISDN(3), Calling IE Present=FALSE,
Source Trkgrp Route Label=, Target Trkgrp Route Label=, CLID Transparent=FALSE), Call Id=-1
104320: *Jan 25 20:41:11.879 Mexico: //-1/188F7F4684E0/CCAPI/ccCheckClipClir:
In: Calling Number=800(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
104321: *Jan 25 20:41:11.879 Mexico: //-1/188F7F4684E0/CCAPI/ccCheckClipClir:
Out: Calling Number=800(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
104322: *Jan 25 20:41:11.879 Mexico: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

104323: *Jan 25 20:41:11.879 Mexico: :cc_get_feature_vsa malloc success
104324: *Jan 25 20:41:11.879 Mexico: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

104325: *Jan 25 20:41:11.879 Mexico: cc_get_feature_vsa count is 1
104326: *Jan 25 20:41:11.879 Mexico: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

104327: *Jan 25 20:41:11.879 Mexico: :FEATURE_VSA attributes are: feature_name:0,feature_time:1010532864,feature_id:5460
104328: *Jan 25 20:41:11.879 Mexico: //6633/188F7F4684E0/CCAPI/cc_api_call_setup_ind_common:
Set Up Event Sent;
Call Info(Calling Number=800(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
Called Number=(TON=Unknown, NPI=Unknown))
104329: *Jan 25 20:41:11.879 Mexico: //-1/xxxxxxxxxxxx/CCAPI/cc_build_feature_vsa:

104330: *Jan 25 20:41:11.879 Mexico: :Inside cc_build_feature_vsa
104331: *Jan 25 20:41:11.879 Mexico: //-1/xxxxxxxxxxxx/CCAPI/cc_build_feature_vsa:

104332: *Jan 25 20:41:11.879 Mexico: feature call basic
104333: *Jan 25 20:41:11.879 Mexico: //-1/xxxxxxxxxxxx/CCAPI/cc_build_feature_vsa:

104334: *Jan 25 20:41:11.879 Mexico: cc_build_feature_vsa attr is fn:TWC,ft:01/25/2016 20:41:11.879,cgn:800,cdn:,frs:0,fid:5460,fcid:188F7F46C30D11E584E0F1D02AE27486,legID:19E9
104335: *Jan 25 20:41:11.879 Mexico: //6633/188F7F4684E0/CCAPI/cc_process_call_setup_ind:
Event=0x40D2A440
104336: *Jan 25 20:41:11.879 Mexico: //6633/188F7F4684E0/CCAPI/ccCallSetContext:
Context=0x3ADAFC38
104337: *Jan 25 20:41:11.879 Mexico: //6633/188F7F4684E0/CCAPI/cc_process_call_setup_ind:
>>>>CCAPI handed cid 6633 with tag 507 to app "_ManagedAppProcess_Default"
104338: *Jan 25 20:41:11.883 Mexico: //6633/188F7F4684E0/CCAPI/ccCallProceeding:
Progress Indication=NULL(0)
104339: *Jan 25 20:41:11.883 Mexico: //6633/188F7F4684E0/CCAPI/ccCallDisconnect:
Cause Value=28, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
104340: *Jan 25 20:41:11.883 Mexico: //6633/188F7F4684E0/CCAPI/ccCallDisconnect:
Cause Value=28, Call Entry(Responsed=TRUE, Cause Value=28)
104341: *Jan 25 20:41:11.883 Mexico: //6633/188F7F4684E0/CCAPI/cc_api_get_transfer_info:
Transfer Number=NULL
104342: *Jan 25 20:41:13.883 Mexico: //6633/188F7F4684E0/CCAPI/cc_api_call_disconnect_done:
Disposition=0, Interface=0x223BF8D0, Tag=0x0, Call Id=6633,
Call Entry(Disconnect Cause=28, Voice Class Cause Code=0, Retry Count=0)
104343: *Jan 25 20:41:13.883 Mexico: //6633/188F7F4684E0/CCAPI/cc_api_call_disconnect_done:
Call Disconnect Event Sent
104344: *Jan 25 20:41:13.883 Mexico: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

104345: *Jan 25 20:41:13.883 Mexico: :cc_free_feature_vsa freeing 3C3B81F8
104346: *Jan 25 20:41:13.883 Mexico: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

104347: *Jan 25 20:41:13.883 Mexico: vsacount in free is 0
104348: *Jan 25 20:42:01.495 Mexico: //-1/3622E91A84E4/CCAPI/cc_api_display_ie_subfields:

attached sh run and sh loggin

Regards.

[Nadeem Ahmed]

dial-peer voice 503 pots
description DIDs Avaya to Cisco Unified Communicatios Manager Express
translation-profile incoming DID2
destination-pattern 800
incoming called-number 800
direct-inward-dial
port 0/1/3
!
dial-peer voice 507 pots
description DIDs Avaya to Cisco Unified Communicatios Manager Express
translation-profile incoming DID2
destination-pattern 800
incoming called-number 800
direct-inward-dial
port 0/2/3

why you are having multiple dial-peer for same destined number also no need for incoming dial-peer 800 just make it  dot (.) . looks it matching 507 dial-peer with ANI and again re-routing with 503 dial-peer . just make one dial-peer with called number as destined number and test call.

this time call debug vpm signal and debug voice vtsp all along ccapi

Br,

Nadeem Ahmed

[fdamian01]

Hi

How to interpret this debug.

different scenarios

voice translation-rule 2
rule 1 /89901/ /800/
!
voice translation-profile DID2
translate called 2

voice-port 0/2/3
supervisory disconnect dualtone pre-connect
supervisory answer dualtone
no battery-reversal
input gain 8
echo-cancel coverage 32
cptone MX
timeouts interdigit 5
timeouts call-disconnect 3
timeouts wait-release 2
caller-id enable

no dial-peer voice 507 pots
description DIDs Avaya to Cisco Unified Communicatios Manager Express
translation-profile incoming DID2
destination-pattern .
incoming called-number .
direct-inward-dial
port 0/2/3

106033: *Jan 25 23:14:18.219 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=61487 systime=12929896
106034: *Jan 25 23:14:18.219 Mexico: htsp_process_event: [0/2/3, FXOLS_ONHOOK, E_DSP_SIG_0000]fxols_onhook_ringing
106035: *Jan 25 23:14:18.219 Mexico: htsp_timer - 125 msec
106036: *Jan 25 23:14:18.347 Mexico: htsp_process_event: [0/2/3, FXOLS_WAIT_RING_MIN, E_HTSP_EVENT_TIMER]fxols_wait_ring_min_timer
106037: *Jan 25 23:14:18.347 Mexico: htsp_timer - 10000 msec
106038: *Jan 25 23:14:18.347 Mexico: htsp_timer3 - 5600 msec
106039: *Jan 25 23:14:18.347 Mexico: [0/2/3] htsp_start_caller_id_rx:Mode BELLCORE. Alerting 0x1
106040: *Jan 25 23:14:18.347 Mexico: htsp_start_caller_id_rx create dsp_stream_manager
106041: *Jan 25 23:14:18.347 Mexico: [0/2/3] htsp_dsm_create_success returns 1
106042: *Jan 25 23:14:19.275 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=62541 systime=12930002
106043: *Jan 25 23:14:19.275 Mexico: htsp_process_event: [0/2/3, FXOLS_RINGING, E_DSP_SIG_0100]
106044: *Jan 25 23:14:19.275 Mexico: fxols_ringing_not
106045: *Jan 25 23:14:19.275 Mexico: htsp_timer_stop
106046: *Jan 25 23:14:19.275 Mexico: htsp_timer - 10000 msec
106047: *Jan 25 23:14:23.223 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=951 systime=12930397
106048: *Jan 25 23:14:23.223 Mexico: htsp_process_event: [0/2/3, FXOLS_RINGING, E_DSP_SIG_0000]
106049: *Jan 25 23:14:23.947 Mexico: htsp_process_event: [0/2/3, FXOLS_RINGING, E_HTSP_EVENT_TIMER3]fxols_snoop_clid_stop
106050: *Jan 25 23:14:23.947 Mexico: htsp_timer_stop3
106051: *Jan 25 23:14:24.275 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=2006 systime=12930502
106052: *Jan 25 23:14:24.275 Mexico: htsp_process_event: [0/2/3, FXOLS_RINGING, E_DSP_SIG_0100]
106053: *Jan 25 23:14:24.275 Mexico: fxols_ringing_not
106054: *Jan 25 23:14:24.275 Mexico: htsp_timer_stop
106055: *Jan 25 23:14:24.275 Mexico: htsp_timer_stop3
106056: *Jan 25 23:14:24.275 Mexico: [0/2/3] htsp_stop_caller_id_rx. message length 0htsp_setup_ind
106057: *Jan 25 23:14:24.275 Mexico: [0/2/3] get_fxo_caller_id:Caller ID receive failed. parseCallerIDString:no data.
106058: *Jan 25 23:14:24.275 Mexico: [0/2/3] get_local_station_id calling num= calling name= calling time=01/25 23:14 orig called=
106059: *Jan 25 23:14:24.283 Mexico: [0/2/3] htsp_dsm_close_done
106060: *Jan 25 23:14:24.283 Mexico: htsp_process_event: [0/2/3, FXOLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]
106061: *Jan 25 23:14:24.283 Mexico: fxols_wait_setup_ack:
106062: *Jan 25 23:14:24.283 Mexico: [0/2/3] set signal state = 0xC timestamp = 0fxols_check_auto_call
106063: *Jan 25 23:14:24.283 Mexico: htsp_process_event: [0/2/3, FXOLS_PROCEEDING, E_HTSP_PROCEEDING]fxols_offhook_proc
106064: *Jan 25 23:14:24.283 Mexico: htsp_timer - 120000 msec
106065: *Jan 25 23:14:24.287 Mexico: htsp_pre_connect_disconnect, cdb = 3C3B2970 cause = 1C

106066: *Jan 25 23:14:24.287 Mexico: htsp_process_event: [0/2/3, FXOLS_PROCEEDING, E_HTSP_PRE_CONN_DISC]
106067: *Jan 25 23:14:24.611 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x6 timestamp=2337 systime=12930536
106068: *Jan 25 23:14:24.611 Mexico: htsp_process_event: [0/2/3, FXOLS_OFFHOOK, E_DSP_SIG_0110]
106069: *Jan 25 23:14:24.611 Mexico: htsp_timer_stop2
106070: *Jan 25 23:14:26.287 Mexico: htsp_process_event: [0/2/3, FXOLS_OFFHOOK, E_HTSP_RELEASE_REQ]fxols_offhook_release
106071: *Jan 25 23:14:26.287 Mexico: htsp_timer_stop
106072: *Jan 25 23:14:26.287 Mexico: htsp_timer_stop2
106073: *Jan 25 23:14:26.287 Mexico: htsp_timer_stop3
106074: *Jan 25 23:14:26.287 Mexico: [0/2/3] set signal state = 0x4 timestamp = 0
106075: *Jan 25 23:14:26.287 Mexico: htsp_timer - 2000 msec
106076: *Jan 25 23:14:26.559 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x6 timestamp=4288 systime=12930730
106077: *Jan 25 23:14:26.559 Mexico: htsp_process_event: [0/2/3, FXOLS_GUARD_OUT, E_DSP_SIG_0110]
106078: *Jan 25 23:14:28.195 Mexico: %SYS-5-CONFIG_I: Configured from console by Administrator on vty0 (192.168.1.30)
106079: *Jan 25 23:14:28.287 Mexico: htsp_process_event: [0/2/3, FXOLS_GUARD_OUT, E_HTSP_EVENT_TIMER]fxols_guard_out_timeout
106080: *Jan 25 23:14:28.291 Mexico: htsp_dsp_message: RESP_SIG_STATUS: state=0x4 timestamp=0 systime=12930904
106081: *Jan 25 23:14:28.291 Mexico: htsp_process_event: [0/2/3, FXOLS_ONHOOK, E_DSP_SIG_0100]

106165: *Jan 25 23:18:38.023 Mexico: //-1/xxxxxxxxxxxx/VTSP:(0/2/3):-1:-1:-1/vtsp_allocate_cdb:
CDB=0x3C3B1830
106166: *Jan 25 23:18:38.023 Mexico: //-1/xxxxxxxxxxxx/VTSP:(0/2/3):-1:-1:-1/vtsp_do_call_setup_ind:
Event=E_TSP_SETUP_IND
Progress Indication=3, CarrierIDCode=, Info Trans Capability=144, Source Carrier ID=, tg_label_flag=0
106167: *Jan 25 23:18:38.023 Mexico: //-1/16E7D02C859B/VTSP:(0/2/3):-1:-1:-1/vtsp_do_normal_call_setup_ind:
106168: *Jan 25 23:18:38.023 Mexico: //-1/16E7D02C859B/VTSP:(0/2/3):-1:-1:-1/vtsp_timer:
Timer Start Time=12955877, Timer Value=180000(ms)
106169: *Jan 25 23:18:38.023 Mexico: //-1/16E7D02C859B/VTSP:(0/2/3):-1:-1:-1/vtsp_do_normal_call_setup_ind:
IC State Machine (ICSM) Added
106170: *Jan 25 23:18:38.023 Mexico: //-1/16E7D02C859B/VTSP:(0/2/3):-1:-1:-1/vtsp_insert_cdb:
106171: *Jan 25 23:18:38.027 Mexico: //-1/16E7D02C859B/VTSP:(0/2/3):-1:1:1/vtsp_dsm_opened_cb:
106172: *Jan 25 23:18:38.027 Mexico: //-1/16E7D02C859B/VTSP:(0/2/3):-1:1:1/vtsp_process_event:
[state:S_SETUP_IND_PEND, event:E_VTSP_DSM_OPEN_SUCCESS]
106173: *Jan 25 23:18:38.031 Mexico: //-1/16E7D02C859B/VTSP:(0/2/3):-1:1:1/act_setup_ind_pend_success:
106174: *Jan 25 23:18:38.031 Mexico: //-1/16E7D02C859B/VTSP:(0/2/3):-1:1:1/vtsp_realloc_cdb:
CDB=0x3C3B1830
106175: *Jan 25 23:18:38.031 Mexico: //-1/16E7D02C859B/VTSP:(0/2/3):-1:1:1/vtsp_indicate_call:
106176: *Jan 25 23:18:38.031 Mexico: //6795/16E7D02C859B/VTSP:(0/2/3):-1:1:1/vtsp_insert_cdb:
106177: *Jan 25 23:18:38.031 Mexico: //6795/16E7D02C859B/VTSP:(0/2/3):-1:1:1/vtsp_timer:
Timer Start Time=12955878, Timer Value=180000(ms)
106178: *Jan 25 23:18:38.031 Mexico: //6795/16E7D02C859B/VTSP:(0/2/3):-1:1:1/vtsp_process_event:
[state:S_SETUP_INDICATED, event:E_CC_PROCEEDING]
106179: *Jan 25 23:18:38.031 Mexico: //6795/16E7D02C859B/VTSP:(0/2/3):-1:1:1/act_proceeding:
Progress Indication=0
106180: *Jan 25 23:18:38.031 Mexico: //6795/16E7D02C859B/VTSP:(0/2/3):-1:1:1/vtsp_timer_stop:
Timer Stop Time=12955878
106181: *Jan 25 23:18:38.031 Mexico: //6795/16E7D02C859B/VTSP:(0/2/3):-1:1:1/vtsp_process_event:
[state:S_PROCEEDING, event:E_CC_DISCONNECT]
106182: *Jan 25 23:18:38.031 Mexico: //6795/16E7D02C859B/VTSP:(0/2/3):-1:1:1/act_pre_con_disconnect:
Cause Value=28, Hairpin=FALSE
106183: *Jan 25 23:18:38.031 Mexico: //6795/16E7D02C859B/VTSP:(0/2/3):-1:1:1/vtsp_timer_stop:
Timer Stop Time=12955878
106184: *Jan 25 23:18:38.031 Mexico: //6795/16E7D02C859B/VTSP:(0/2/3):-1:1:1/vtsp_ring_noan_timer_stop:
Timer Stop Time=12955878
106185: *Jan 25 23:18:38.031 Mexico: //6795/16E7D02C859B/VTSP:(0/2/3):-1:1:1/act_pre_con_disconnect:
[Number Unobtainable]-Tone Played In Direction [Network]
106186: *Jan 25 23:18:38.035 Mexico: //6795/16E7D02C859B/VTSP:(0/2/3):-1:1:1/vtsp_timer:
Timer Start Time=12955878, Timer Value=2000(ms)
106187: *Jan 25 23:18:38.035 Mexico: //6795/16E7D02C859B/VTSP:(0/2/3):-1:1:1/act_pre_con_disconnect:
Tone=Number Unobtainable, Tone Timeout=2(s), Progress Indication Sent=0
106188: *Jan 25 23:18:40.035 Mexico: //6795/16E7D02C859B/VTSP:(0/2/3):-1:1:1/vtsp_process_event:
[state:S_WAIT_RELEASE_NC, event:E_TIMER]
106189: *Jan 25 23:18:40.035 Mexico: //6795/16E7D02C859B/VTSP:(0/2/3):-1:1:1/act_pre_con_disc_rel:
106190: *Jan 25 23:18:40.035 Mexico: //6795/16E7D02C859B/VTSP:(0/2/3):-1:1:1/act_pre_con_disc_rel:
Cause Value=28
106191: *Jan 25 23:18:40.035 Mexico: //6795/16E7D02C859B/VTSP:(0/2/3):-1:1:1/vtsp_process_event:
[state:S_WAIT_RELEASE_RESP, event:E_TSP_DISCONNECT_CONF]
106192: *Jan 25 23:18:40.035 Mexico: //6795/16E7D02C859B/VTSP:(0/2/3):-1:1:1/act_wrelease_release:
106193: *Jan 25 23:18:40.035 Mexico: //6795/16E7D02C859B/VTSP:(0/2/3):-1:1:1/vtsp_play_busy_timer_stop:
Timer Stop Time=12956078
106194: *Jan 25 23:18:40.035 Mexico: //6795/16E7D02C859B/VTSP:(0/2/3):-1:1:1/vtsp_timer_stop:
Timer Stop Time=12956078
106195: *Jan 25 23:18:40.035 Mexico: //6795/16E7D02C859B/VTSP:(0/2/3):-1:1:1/vtsp_do_call_history:
106196: *Jan 25 23:18:40.035 Mexico: //6795/16E7D02C859B/VTSP:(0/2/3):-1:1:1/vtsp_do_call_history:
Coder Rate=-1
106197: *Jan 25 23:18:40.035 Mexico: //6795/16E7D02C859B/VTSP:(0/2/3):-1:1:1/vtsp_is_valid_dsm_handle:
DMGR=0x3E58FB78, VTSP CDB=0x3C3B1830
106198: *Jan 25 23:18:40.035 Mexico: //6795/16E7D02C859B/VTSP:(0/2/3):-1:-1:-1/vtsp_dsm_closed_cb:
106199: *Jan 25 23:18:40.035 Mexico: //6795/16E7D02C859B/VTSP:(0/2/3):-1:-1:-1/vtsp_process_event:
[state:S_CLOSE_DSPRM, event:E_VTSP_DSM_CLOSE_COMPLETE]
106200: *Jan 25 23:18:40.035 Mexico: //6795/16E7D02C859B/VTSP:(0/2/3):-1:-1:-1/act_terminate:
106201: *Jan 25 23:18:40.035 Mexico: //6795/16E7D02C859B/VTSP:(0/2/3):-1:-1:-1/vtsp_timer_stop:
Timer Stop Time=12956078
106202: *Jan 25 23:18:40.035 Mexico: //-1/16E7D02C859B/VTSP:(0/2/3):-1:-1:-1/vtsp_free_cdb:
CDB=0x3C3B1830
GNP_GATEWAY#

voice translation-rule 2
rule 1 /89901/ /800/
!
voice translation-profile DID2
translate called 2

voice-port 0/2/3
supervisory disconnect dualtone pre-connect
supervisory answer dualtone
no battery-reversal
input gain 8
echo-cancel coverage 32
cptone MX
timeouts interdigit 5
timeouts call-disconnect 3
timeouts wait-release 2
caller-id enable

dial-peer voice 507 pots
description DIDs Avaya to Cisco Unified Communicatios Manager Express
translation-profile incoming DID2
destination-pattern .
incoming called-number 800
direct-inward-dial
port 0/2/3

106329: *Jan 25 23:30:19.459 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=39715 systime=13026020
106330: *Jan 25 23:30:19.459 Mexico: htsp_process_event: [0/2/3, FXOLS_ONHOOK, E_DSP_SIG_0000]fxols_onhook_ringing
106331: *Jan 25 23:30:19.459 Mexico: htsp_timer - 125 msec
106332: *Jan 25 23:30:19.587 Mexico: htsp_process_event: [0/2/3, FXOLS_WAIT_RING_MIN, E_HTSP_EVENT_TIMER]fxols_wait_ring_min_timer
106333: *Jan 25 23:30:19.587 Mexico: htsp_timer - 10000 msec
106334: *Jan 25 23:30:19.587 Mexico: htsp_timer3 - 5600 msec
106335: *Jan 25 23:30:19.587 Mexico: [0/2/3] htsp_start_caller_id_rx:Mode BELLCORE. Alerting 0x1
106336: *Jan 25 23:30:19.587 Mexico: htsp_start_caller_id_rx create dsp_stream_manager
106337: *Jan 25 23:30:19.587 Mexico: [0/2/3] htsp_dsm_create_success returns 1
106338: *Jan 25 23:30:20.515 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=40770 systime=13026126
106339: *Jan 25 23:30:20.515 Mexico: htsp_process_event: [0/2/3, FXOLS_RINGING, E_DSP_SIG_0100]
106340: *Jan 25 23:30:20.515 Mexico: fxols_ringing_not
106341: *Jan 25 23:30:20.515 Mexico: htsp_timer_stop
106342: *Jan 25 23:30:20.515 Mexico: htsp_timer - 10000 msec
106343: *Jan 25 23:30:24.463 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=44715 systime=13026521
106344: *Jan 25 23:30:24.463 Mexico: htsp_process_event: [0/2/3, FXOLS_RINGING, E_DSP_SIG_0000]
106345: *Jan 25 23:30:25.187 Mexico: htsp_process_event: [0/2/3, FXOLS_RINGING, E_HTSP_EVENT_TIMER3]fxols_snoop_clid_stop
106346: *Jan 25 23:30:25.187 Mexico: htsp_timer_stop3
106347: *Jan 25 23:30:25.515 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=45770 systime=13026626
106348: *Jan 25 23:30:25.527 Mexico: htsp_process_event: [0/2/3, FXOLS_RINGING, E_DSP_SIG_0100]
106349: *Jan 25 23:30:25.527 Mexico: fxols_ringing_not
106350: *Jan 25 23:30:25.527 Mexico: htsp_timer_stop
106351: *Jan 25 23:30:25.527 Mexico: htsp_timer_stop3
106352: *Jan 25 23:30:25.527 Mexico: [0/2/3] htsp_stop_caller_id_rx. message length 0htsp_setup_ind
106353: *Jan 25 23:30:25.527 Mexico: [0/2/3] get_fxo_caller_id:Caller ID receive failed. parseCallerIDString:no data.
106354: *Jan 25 23:30:25.527 Mexico: [0/2/3] get_local_station_id calling num= calling name= calling time=01/25 23:30 orig called=
106355: *Jan 25 23:30:25.527 Mexico: //-1/xxxxxxxxxxxx/VTSP:(0/2/3):-1:-1:-1/vtsp_allocate_cdb:
CDB=0x3C3B23B0
106356: *Jan 25 23:30:25.527 Mexico: //-1/xxxxxxxxxxxx/VTSP:(0/2/3):-1:-1:-1/vtsp_do_call_setup_ind:
Event=E_TSP_SETUP_IND
Progress Indication=3, CarrierIDCode=, Info Trans Capability=144, Source Carrier ID=, tg_label_flag=0
106357: *Jan 25 23:30:25.527 Mexico: //-1/BC9C57B085B1/VTSP:(0/2/3):-1:-1:-1/vtsp_do_normal_call_setup_ind:
106358: *Jan 25 23:30:25.527 Mexico: //-1/BC9C57B085B1/VTSP:(0/2/3):-1:-1:-1/vtsp_timer:
Timer Start Time=13026627, Timer Value=180000(ms)
106359: *Jan 25 23:30:25.527 Mexico: //-1/BC9C57B085B1/VTSP:(0/2/3):-1:-1:-1/vtsp_do_normal_call_setup_ind:
IC State Machine (ICSM) Added
106360: *Jan 25 23:30:25.527 Mexico: //-1/BC9C57B085B1/VTSP:(0/2/3):-1:-1:-1/vtsp_insert_cdb:
106361: *Jan 25 23:30:25.595 Mexico: //-1/BC9C57B085B1/VTSP:(0/2/3):-1:1:1/vtsp_dsm_opened_cb:
106362: *Jan 25 23:30:25.595 Mexico: //-1/BC9C57B085B1/VTSP:(0/2/3):-1:1:1/vtsp_process_event:
[state:S_SETUP_IND_PEND, event:E_VTSP_DSM_OPEN_SUCCESS]
106363: *Jan 25 23:30:25.595 Mexico: //-1/BC9C57B085B1/VTSP:(0/2/3):-1:1:1/act_setup_ind_pend_success:
106364: *Jan 25 23:30:25.595 Mexico: //-1/BC9C57B085B1/VTSP:(0/2/3):-1:1:1/vtsp_realloc_cdb:
CDB=0x3C3B23B0
106365: *Jan 25 23:30:25.595 Mexico: //-1/BC9C57B085B1/VTSP:(0/2/3):-1:1:1/vtsp_indicate_call:
106366: *Jan 25 23:30:25.595 Mexico: //6808/BC9C57B085B1/VTSP:(0/2/3):-1:1:1/vtsp_insert_cdb:
106367: *Jan 25 23:30:25.599 Mexico: //6808/BC9C57B085B1/VTSP:(0/2/3):-1:1:1/vtsp_timer:
Timer Start Time=13026634, Timer Value=180000(ms)
106368: *Jan 25 23:30:25.599 Mexico: [0/2/3] htsp_dsm_close_done
106369: *Jan 25 23:30:25.599 Mexico: htsp_process_event: [0/2/3, FXOLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]
106370: *Jan 25 23:30:25.599 Mexico: fxols_wait_setup_ack:
106371: *Jan 25 23:30:25.599 Mexico: [0/2/3] set signal state = 0xC timestamp = 0fxols_check_auto_call
106372: *Jan 25 23:30:25.599 Mexico: //6808/BC9C57B085B1/VTSP:(0/2/3):-1:1:1/vtsp_process_event:
[state:S_SETUP_INDICATED, event:E_CC_PROCEEDING]
106373: *Jan 25 23:30:25.599 Mexico: //6808/BC9C57B085B1/VTSP:(0/2/3):-1:1:1/act_proceeding:
Progress Indication=0
106374: *Jan 25 23:30:25.599 Mexico: //6808/BC9C57B085B1/VTSP:(0/2/3):-1:1:1/vtsp_timer_stop:
Timer Stop Time=13026634
106375: *Jan 25 23:30:25.599 Mexico: htsp_process_event: [0/2/3, FXOLS_PROCEEDING, E_HTSP_PROCEEDING]fxols_offhook_proc
106376: *Jan 25 23:30:25.599 Mexico: htsp_timer - 120000 msec
106377: *Jan 25 23:30:25.599 Mexico: //6808/BC9C57B085B1/VTSP:(0/2/3):-1:1:1/vtsp_process_event:
[state:S_PROCEEDING, event:E_CC_DISCONNECT]
106378: *Jan 25 23:30:25.599 Mexico: //6808/BC9C57B085B1/VTSP:(0/2/3):-1:1:1/act_pre_con_disconnect:
Cause Value=28, Hairpin=FALSE
106379: *Jan 25 23:30:25.599 Mexico: //6808/BC9C57B085B1/VTSP:(0/2/3):-1:1:1/vtsp_timer_stop:
Timer Stop Time=13026634
106380: *Jan 25 23:30:25.599 Mexico: //6808/BC9C57B085B1/VTSP:(0/2/3):-1:1:1/vtsp_ring_noan_timer_stop:
Timer Stop Time=13026634
106381: *Jan 25 23:30:25.599 Mexico: //6808/BC9C57B085B1/VTSP:(0/2/3):-1:1:1/act_pre_con_disconnect:
[Number Unobtainable]-Tone Played In Direction [Network]
106382: *Jan 25 23:30:25.599 Mexico: //6808/BC9C57B085B1/VTSP:(0/2/3):-1:1:1/vtsp_timer:
Timer Start Time=13026634, Timer Value=2000(ms)
106383: *Jan 25 23:30:25.599 Mexico: htsp_pre_connect_disconnect, cdb = 3C3B23B0 cause = 1C

106384: *Jan 25 23:30:25.599 Mexico: //6808/BC9C57B085B1/VTSP:(0/2/3):-1:1:1/act_pre_con_disconnect:
Tone=Number Unobtainable, Tone Timeout=2(s), Progress Indication Sent=0
106385: *Jan 25 23:30:25.599 Mexico: htsp_process_event: [0/2/3, FXOLS_PROCEEDING, E_HTSP_PRE_CONN_DISC]
106386: *Jan 25 23:30:25.923 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x6 timestamp=46177 systime=13026667
106387: *Jan 25 23:30:25.923 Mexico: htsp_process_event: [0/2/3, FXOLS_OFFHOOK, E_DSP_SIG_0110]
106388: *Jan 25 23:30:25.923 Mexico: htsp_timer_stop2
106389: *Jan 25 23:30:27.599 Mexico: //6808/BC9C57B085B1/VTSP:(0/2/3):-1:1:1/vtsp_process_event:
[state:S_WAIT_RELEASE_NC, event:E_TIMER]
106390: *Jan 25 23:30:27.599 Mexico: //6808/BC9C57B085B1/VTSP:(0/2/3):-1:1:1/act_pre_con_disc_rel:
106391: *Jan 25 23:30:27.599 Mexico: //6808/BC9C57B085B1/VTSP:(0/2/3):-1:1:1/act_pre_con_disc_rel:
Cause Value=28
106392: *Jan 25 23:30:27.599 Mexico: htsp_process_event: [0/2/3, FXOLS_OFFHOOK, E_HTSP_RELEASE_REQ]fxols_offhook_release
106393: *Jan 25 23:30:27.599 Mexico: htsp_timer_stop
106394: *Jan 25 23:30:27.599 Mexico: htsp_timer_stop2
106395: *Jan 25 23:30:27.599 Mexico: htsp_timer_stop3
106396: *Jan 25 23:30:27.599 Mexico: [0/2/3] set signal state = 0x4 timestamp = 0
106397: *Jan 25 23:30:27.599 Mexico: htsp_timer - 2000 msec
106398: *Jan 25 23:30:27.599 Mexico: //6808/BC9C57B085B1/VTSP:(0/2/3):-1:1:1/vtsp_process_event:
[state:S_WAIT_RELEASE_RESP, event:E_TSP_DISCONNECT_CONF]
106399: *Jan 25 23:30:27.599 Mexico: //6808/BC9C57B085B1/VTSP:(0/2/3):-1:1:1/act_wrelease_release:
106400: *Jan 25 23:30:27.599 Mexico: //6808/BC9C57B085B1/VTSP:(0/2/3):-1:1:1/vtsp_play_busy_timer_stop:
Timer Stop Time=13026834
106401: *Jan 25 23:30:27.599 Mexico: //6808/BC9C57B085B1/VTSP:(0/2/3):-1:1:1/vtsp_timer_stop:
Timer Stop Time=13026834
106402: *Jan 25 23:30:27.599 Mexico: //6808/BC9C57B085B1/VTSP:(0/2/3):-1:1:1/vtsp_do_call_history:
106403: *Jan 25 23:30:27.599 Mexico: //6808/BC9C57B085B1/VTSP:(0/2/3):-1:1:1/vtsp_do_call_history:
Coder Rate=-1
106404: *Jan 25 23:30:27.599 Mexico: //6808/BC9C57B085B1/VTSP:(0/2/3):-1:1:1/vtsp_is_valid_dsm_handle:
DMGR=0x42731810, VTSP CDB=0x3C3B23B0
106405: *Jan 25 23:30:27.599 Mexico: //6808/BC9C57B085B1/VTSP:(0/2/3):-1:-1:-1/vtsp_dsm_closed_cb:
106406: *Jan 25 23:30:27.599 Mexico: //6808/BC9C57B085B1/VTSP:(0/2/3):-1:-1:-1/vtsp_process_event:
[state:S_CLOSE_DSPRM, event:E_VTSP_DSM_CLOSE_COMPLETE]
106407: *Jan 25 23:30:27.599 Mexico: //6808/BC9C57B085B1/VTSP:(0/2/3):-1:-1:-1/act_terminate:
106408: *Jan 25 23:30:27.599 Mexico: //6808/BC9C57B085B1/VTSP:(0/2/3):-1:-1:-1/vtsp_timer_stop:
Timer Stop Time=13026834
106409: *Jan 25 23:30:27.599 Mexico: //-1/BC9C57B085B1/VTSP:(0/2/3):-1:-1:-1/vtsp_free_cdb:
CDB=0x3C3B23B0
106410: *Jan 25 23:30:27.871 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x6 timestamp=48125 systime=13026862
106411: *Jan 25 23:30:27.871 Mexico: htsp_process_event: [0/2/3, FXOLS_GUARD_OUT, E_DSP_SIG_0110]
GNP_GATEWAY#

voice translation-rule 2
rule 1 /89901/ /800/
!
voice translation-profile DID2
translate called 2

voice-port 0/2/3
supervisory disconnect dualtone pre-connect
supervisory answer dualtone
no battery-reversal
input gain 8
echo-cancel coverage 32
cptone MX
timeouts interdigit 5
timeouts call-disconnect 3
timeouts wait-release 2
caller-id enable

dial-peer voice 507 pots
description DIDs Avaya to Cisco Unified Communicatios Manager Express
translation-profile incoming DID2
destination-pattern .
incoming called-number 89901
direct-inward-dial
port 0/2/3

106578: *Jan 25 23:34:36.959 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=35076 systime=13051770
106579: *Jan 25 23:34:36.959 Mexico: htsp_process_event: [0/2/3, FXOLS_ONHOOK, E_DSP_SIG_0000]fxols_onhook_ringing
106580: *Jan 25 23:34:36.959 Mexico: htsp_timer - 125 msec
106581: *Jan 25 23:34:37.087 Mexico: htsp_process_event: [0/2/3, FXOLS_WAIT_RING_MIN, E_HTSP_EVENT_TIMER]fxols_wait_ring_min_timer
106582: *Jan 25 23:34:37.087 Mexico: htsp_timer - 10000 msec
106583: *Jan 25 23:34:37.087 Mexico: htsp_timer3 - 5600 msec
106584: *Jan 25 23:34:37.087 Mexico: [0/2/3] htsp_start_caller_id_rx:Mode BELLCORE. Alerting 0x1
106585: *Jan 25 23:34:37.087 Mexico: htsp_start_caller_id_rx create dsp_stream_manager
106586: *Jan 25 23:34:37.087 Mexico: [0/2/3] htsp_dsm_create_success returns 1
106587: *Jan 25 23:34:38.011 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=36131 systime=13051876
106588: *Jan 25 23:34:38.011 Mexico: htsp_process_event: [0/2/3, FXOLS_RINGING, E_DSP_SIG_0100]
106589: *Jan 25 23:34:38.015 Mexico: fxols_ringing_not
106590: *Jan 25 23:34:38.015 Mexico: htsp_timer_stop
106591: *Jan 25 23:34:38.015 Mexico: htsp_timer - 10000 msec
106592: *Jan 25 23:34:41.959 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=40076 systime=13052270
106593: *Jan 25 23:34:41.959 Mexico: htsp_process_event: [0/2/3, FXOLS_RINGING, E_DSP_SIG_0000]
106594: *Jan 25 23:34:42.687 Mexico: htsp_process_event: [0/2/3, FXOLS_RINGING, E_HTSP_EVENT_TIMER3]fxols_snoop_clid_stop
106595: *Jan 25 23:34:42.687 Mexico: htsp_timer_stop3
106596: *Jan 25 23:34:43.015 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=41131 systime=13052376
106597: *Jan 25 23:34:43.015 Mexico: htsp_process_event: [0/2/3, FXOLS_RINGING, E_DSP_SIG_0100]
106598: *Jan 25 23:34:43.015 Mexico: fxols_ringing_not
106599: *Jan 25 23:34:43.015 Mexico: htsp_timer_stop
106600: *Jan 25 23:34:43.015 Mexico: htsp_timer_stop3
106601: *Jan 25 23:34:43.015 Mexico: [0/2/3] htsp_stop_caller_id_rx. message length 0htsp_setup_ind
106602: *Jan 25 23:34:43.015 Mexico: [0/2/3] get_fxo_caller_id:Caller ID receive failed. parseCallerIDString:no data.
106603: *Jan 25 23:34:43.015 Mexico: [0/2/3] get_local_station_id calling num= calling name= calling time=01/25 23:34 orig called=
106604: *Jan 25 23:34:43.015 Mexico: //-1/xxxxxxxxxxxx/VTSP:(0/2/3):-1:-1:-1/vtsp_allocate_cdb:
CDB=0x3C3B2C50
106605: *Jan 25 23:34:43.015 Mexico: //-1/xxxxxxxxxxxx/VTSP:(0/2/3):-1:-1:-1/vtsp_do_call_setup_ind:
Event=E_TSP_SETUP_IND
Progress Indication=3, CarrierIDCode=, Info Trans Capability=144, Source Carrier ID=, tg_label_flag=0
106606: *Jan 25 23:34:43.015 Mexico: //-1/5615E56285BD/VTSP:(0/2/3):-1:-1:-1/vtsp_do_normal_call_setup_ind:
106607: *Jan 25 23:34:43.015 Mexico: //-1/5615E56285BD/VTSP:(0/2/3):-1:-1:-1/vtsp_timer:
Timer Start Time=13052376, Timer Value=180000(ms)
106608: *Jan 25 23:34:43.015 Mexico: //-1/5615E56285BD/VTSP:(0/2/3):-1:-1:-1/vtsp_do_normal_call_setup_ind:
IC State Machine (ICSM) Added
106609: *Jan 25 23:34:43.015 Mexico: //-1/5615E56285BD/VTSP:(0/2/3):-1:-1:-1/vtsp_insert_cdb:
106610: *Jan 25 23:34:43.019 Mexico: //-1/5615E56285BD/VTSP:(0/2/3):-1:1:1/vtsp_dsm_opened_cb:
106611: *Jan 25 23:34:43.019 Mexico: //-1/5615E56285BD/VTSP:(0/2/3):-1:1:1/vtsp_process_event:
[state:S_SETUP_IND_PEND, event:E_VTSP_DSM_OPEN_SUCCESS]
106612: *Jan 25 23:34:43.019 Mexico: //-1/5615E56285BD/VTSP:(0/2/3):-1:1:1/act_setup_ind_pend_success:
106613: *Jan 25 23:34:43.019 Mexico: //-1/5615E56285BD/VTSP:(0/2/3):-1:1:1/vtsp_realloc_cdb:
CDB=0x3C3B2C50
106614: *Jan 25 23:34:43.019 Mexico: //-1/5615E56285BD/VTSP:(0/2/3):-1:1:1/vtsp_indicate_call:
106615: *Jan 25 23:34:43.019 Mexico: //6811/5615E56285BD/VTSP:(0/2/3):-1:1:1/vtsp_insert_cdb:
106616: *Jan 25 23:34:43.023 Mexico: //6811/5615E56285BD/VTSP:(0/2/3):-1:1:1/vtsp_timer:
Timer Start Time=13052377, Timer Value=180000(ms)
106617: *Jan 25 23:34:43.023 Mexico: [0/2/3] htsp_dsm_close_done
106618: *Jan 25 23:34:43.023 Mexico: htsp_process_event: [0/2/3, FXOLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]
106619: *Jan 25 23:34:43.023 Mexico: fxols_wait_setup_ack:
106620: *Jan 25 23:34:43.023 Mexico: [0/2/3] set signal state = 0xC timestamp = 0fxols_check_auto_call
106621: *Jan 25 23:34:43.023 Mexico: //6811/5615E56285BD/VTSP:(0/2/3):-1:1:1/vtsp_process_event:
[state:S_SETUP_INDICATED, event:E_CC_PROCEEDING]
106622: *Jan 25 23:34:43.023 Mexico: //6811/5615E56285BD/VTSP:(0/2/3):-1:1:1/act_proceeding:
Progress Indication=0
106623: *Jan 25 23:34:43.023 Mexico: //6811/5615E56285BD/VTSP:(0/2/3):-1:1:1/vtsp_timer_stop:
Timer Stop Time=13052377
106624: *Jan 25 23:34:43.023 Mexico: htsp_process_event: [0/2/3, FXOLS_PROCEEDING, E_HTSP_PROCEEDING]fxols_offhook_proc
106625: *Jan 25 23:34:43.023 Mexico: htsp_timer - 120000 msec
106626: *Jan 25 23:34:43.023 Mexico: //6811/5615E56285BD/VTSP:(0/2/3):-1:1:1/vtsp_process_event:
[state:S_PROCEEDING, event:E_CC_DISCONNECT]
106627: *Jan 25 23:34:43.023 Mexico: //6811/5615E56285BD/VTSP:(0/2/3):-1:1:1/act_pre_con_disconnect:
Cause Value=28, Hairpin=FALSE
106628: *Jan 25 23:34:43.023 Mexico: //6811/5615E56285BD/VTSP:(0/2/3):-1:1:1/vtsp_timer_stop:
Timer Stop Time=13052377
106629: *Jan 25 23:34:43.023 Mexico: //6811/5615E56285BD/VTSP:(0/2/3):-1:1:1/vtsp_ring_noan_timer_stop:
Timer Stop Time=13052377
106630: *Jan 25 23:34:43.023 Mexico: //6811/5615E56285BD/VTSP:(0/2/3):-1:1:1/act_pre_con_disconnect:
[Number Unobtainable]-Tone Played In Direction [Network]
106631: *Jan 25 23:34:43.023 Mexico: //6811/5615E56285BD/VTSP:(0/2/3):-1:1:1/vtsp_timer:
Timer Start Time=13052377, Timer Value=2000(ms)
106632: *Jan 25 23:34:43.023 Mexico: htsp_pre_connect_disconnect, cdb = 3C3B2C50 cause = 1C

106633: *Jan 25 23:34:43.023 Mexico: //6811/5615E56285BD/VTSP:(0/2/3):-1:1:1/act_pre_con_disconnect:
Tone=Number Unobtainable, Tone Timeout=2(s), Progress Indication Sent=0
106634: *Jan 25 23:34:43.023 Mexico: htsp_process_event: [0/2/3, FXOLS_PROCEEDING, E_HTSP_PRE_CONN_DISC]
106635: *Jan 25 23:34:43.343 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x6 timestamp=41462 systime=13052409
106636: *Jan 25 23:34:43.343 Mexico: htsp_process_event: [0/2/3, FXOLS_OFFHOOK, E_DSP_SIG_0110]
106637: *Jan 25 23:34:43.343 Mexico: htsp_timer_stop2
106638: *Jan 25 23:34:45.023 Mexico: //6811/5615E56285BD/VTSP:(0/2/3):-1:1:1/vtsp_process_event:
[state:S_WAIT_RELEASE_NC, event:E_TIMER]
106639: *Jan 25 23:34:45.023 Mexico: //6811/5615E56285BD/VTSP:(0/2/3):-1:1:1/act_pre_con_disc_rel:
106640: *Jan 25 23:34:45.023 Mexico: //6811/5615E56285BD/VTSP:(0/2/3):-1:1:1/act_pre_con_disc_rel:
Cause Value=28
106641: *Jan 25 23:34:45.023 Mexico: htsp_process_event: [0/2/3, FXOLS_OFFHOOK, E_HTSP_RELEASE_REQ]fxols_offhook_release
106642: *Jan 25 23:34:45.023 Mexico: htsp_timer_stop
106643: *Jan 25 23:34:45.023 Mexico: htsp_timer_stop2
106644: *Jan 25 23:34:45.023 Mexico: htsp_timer_stop3
106645: *Jan 25 23:34:45.023 Mexico: [0/2/3] set signal state = 0x4 timestamp = 0
106646: *Jan 25 23:34:45.023 Mexico: htsp_timer - 2000 msec
106647: *Jan 25 23:34:45.023 Mexico: //6811/5615E56285BD/VTSP:(0/2/3):-1:1:1/vtsp_process_event:
[state:S_WAIT_RELEASE_RESP, event:E_TSP_DISCONNECT_CONF]
106648: *Jan 25 23:34:45.023 Mexico: //6811/5615E56285BD/VTSP:(0/2/3):-1:1:1/act_wrelease_release:
106649: *Jan 25 23:34:45.023 Mexico: //6811/5615E56285BD/VTSP:(0/2/3):-1:1:1/vtsp_play_busy_timer_stop:
Timer Stop Time=13052577
106650: *Jan 25 23:34:45.023 Mexico: //6811/5615E56285BD/VTSP:(0/2/3):-1:1:1/vtsp_timer_stop:
Timer Stop Time=13052577
106651: *Jan 25 23:34:45.023 Mexico: //6811/5615E56285BD/VTSP:(0/2/3):-1:1:1/vtsp_do_call_history:
106652: *Jan 25 23:34:45.023 Mexico: //6811/5615E56285BD/VTSP:(0/2/3):-1:1:1/vtsp_do_call_history:
Coder Rate=-1
106653: *Jan 25 23:34:45.023 Mexico: //6811/5615E56285BD/VTSP:(0/2/3):-1:1:1/vtsp_is_valid_dsm_handle:
DMGR=0x3E58FB78, VTSP CDB=0x3C3B2C50
106654: *Jan 25 23:34:45.023 Mexico: //6811/5615E56285BD/VTSP:(0/2/3):-1:-1:-1/vtsp_dsm_closed_cb:
106655: *Jan 25 23:34:45.023 Mexico: //6811/5615E56285BD/VTSP:(0/2/3):-1:-1:-1/vtsp_process_event:
[state:S_CLOSE_DSPRM, event:E_VTSP_DSM_CLOSE_COMPLETE]
106656: *Jan 25 23:34:45.023 Mexico: //6811/5615E56285BD/VTSP:(0/2/3):-1:-1:-1/act_terminate:
106657: *Jan 25 23:34:45.023 Mexico: //6811/5615E56285BD/VTSP:(0/2/3):-1:-1:-1/vtsp_timer_stop:
Timer Stop Time=13052577
106658: *Jan 25 23:34:45.023 Mexico: //-1/5615E56285BD/VTSP:(0/2/3):-1:-1:-1/vtsp_free_cdb:
CDB=0x3C3B2C50
106659: *Jan 25 23:34:45.295 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x6 timestamp=43412 systime=13052604
106660: *Jan 25 23:34:45.295 Mexico: htsp_process_event: [0/2/3, FXOLS_GUARD_OUT, E_DSP_SIG_0110]
GATEWAY#

Regards.

[fdamian01]

changing the port settings

voice-port 0/2/3
supervisory disconnect dualtone pre-connect
supervisory answer dualtone
no battery-reversal
input gain 8
echo-cancel coverage 32
cptone MX
timeouts interdigit 5
timeouts call-disconnect 3
timeouts wait-release 2
caller-id enable
caller-id alerting ring 4

dial-peer voice 507 pots
description DIDs Avaya to Cisco Unified Communicatios Manager Express
translation-profile incoming DID2
destination-pattern .
incoming called-number .
direct-inward-dial
port 0/2/3

107535: *Jan 26 00:13:21.934 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=826 systime=13284268
107536: *Jan 26 00:13:21.934 Mexico: htsp_process_event: [0/2/3, FXOLS_ONHOOK, E_DSP_SIG_0000]fxols_onhook_ringing
107537: *Jan 26 00:13:21.934 Mexico: htsp_timer - 125 msec
107538: *Jan 26 00:13:22.062 Mexico: htsp_process_event: [0/2/3, FXOLS_WAIT_RING_MIN, E_HTSP_EVENT_TIMER]fxols_wait_ring_min_timer
107539: *Jan 26 00:13:22.062 Mexico: htsp_timer - 10000 msec
107540: *Jan 26 00:13:22.062 Mexico: htsp_timer3 - 5600 msec
107541: *Jan 26 00:13:22.062 Mexico: [0/2/3] htsp_start_caller_id_rx:Mode BELLCORE. Alerting 0x1
107542: *Jan 26 00:13:22.062 Mexico: htsp_start_caller_id_rx create dsp_stream_manager
107543: *Jan 26 00:13:22.062 Mexico: [0/2/3] htsp_dsm_create_success returns 1
107544: *Jan 26 00:13:22.986 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=1880 systime=13284373
107545: *Jan 26 00:13:22.986 Mexico: htsp_process_event: [0/2/3, FXOLS_RINGING, E_DSP_SIG_0100]
107546: *Jan 26 00:13:22.986 Mexico: fxols_ringing_not
107547: *Jan 26 00:13:22.986 Mexico: htsp_timer_stop
107548: *Jan 26 00:13:22.986 Mexico: htsp_timer - 10000 msec
107549: *Jan 26 00:13:26.934 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=5826 systime=13284768
107550: *Jan 26 00:13:26.934 Mexico: htsp_process_event: [0/2/3, FXOLS_RINGING, E_DSP_SIG_0000]
107551: *Jan 26 00:13:27.662 Mexico: htsp_process_event: [0/2/3, FXOLS_RINGING, E_HTSP_EVENT_TIMER3]fxols_snoop_clid_stop
107552: *Jan 26 00:13:27.662 Mexico: htsp_timer_stop3
107553: *Jan 26 00:13:27.990 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=6881 systime=13284874
107554: *Jan 26 00:13:27.990 Mexico: htsp_process_event: [0/2/3, FXOLS_RINGING, E_DSP_SIG_0100]
107555: *Jan 26 00:13:27.990 Mexico: fxols_ringing_not
107556: *Jan 26 00:13:27.990 Mexico: htsp_timer_stop
107557: *Jan 26 00:13:27.990 Mexico: htsp_timer - 10000 msec
107558: *Jan 26 00:13:31.934 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=10826 systime=13285268
107559: *Jan 26 00:13:31.934 Mexico: htsp_process_event: [0/2/3, FXOLS_RINGING, E_DSP_SIG_0000]
107560: *Jan 26 00:13:32.990 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=11880 systime=13285374
107561: *Jan 26 00:13:32.990 Mexico: htsp_process_event: [0/2/3, FXOLS_RINGING, E_DSP_SIG_0100]
107562: *Jan 26 00:13:32.990 Mexico: fxols_ringing_not
107563: *Jan 26 00:13:32.990 Mexico: htsp_timer_stop
107564: *Jan 26 00:13:32.990 Mexico: htsp_timer - 10000 msec
107565: *Jan 26 00:13:36.934 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=15826 systime=13285768
107566: *Jan 26 00:13:36.934 Mexico: htsp_process_event: [0/2/3, FXOLS_RINGING, E_DSP_SIG_0000]
107567: *Jan 26 00:13:37.986 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=16880 systime=13285873
107568: *Jan 26 00:13:37.986 Mexico: htsp_process_event: [0/2/3, FXOLS_RINGING, E_DSP_SIG_0100]
107569: *Jan 26 00:13:37.986 Mexico: fxols_ringing_not
107570: *Jan 26 00:13:37.986 Mexico: htsp_timer_stop
107571: *Jan 26 00:13:37.986 Mexico: htsp_timer - 10000 msec
107572: *Jan 26 00:13:41.934 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=20826 systime=13286268
107573: *Jan 26 00:13:41.934 Mexico: htsp_process_event: [0/2/3, FXOLS_RINGING, E_DSP_SIG_0000]
107574: *Jan 26 00:13:42.986 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=21880 systime=13286373
107575: *Jan 26 00:13:42.990 Mexico: htsp_process_event: [0/2/3, FXOLS_RINGING, E_DSP_SIG_0100]
107576: *Jan 26 00:13:42.990 Mexico: fxols_ringing_not
107577: *Jan 26 00:13:42.990 Mexico: htsp_timer_stop
107578: *Jan 26 00:13:42.990 Mexico: htsp_timer_stop3
107579: *Jan 26 00:13:42.990 Mexico: [0/2/3] htsp_stop_caller_id_rx. message length 0htsp_setup_ind
107580: *Jan 26 00:13:42.990 Mexico: [0/2/3] get_fxo_caller_id:Caller ID receive failed. parseCallerIDString:no data.
107581: *Jan 26 00:13:42.990 Mexico: [0/2/3] get_local_station_id calling num= calling name= calling time=01/26 00:13 orig called=
107582: *Jan 26 00:13:42.990 Mexico: //-1/xxxxxxxxxxxx/VTSP:(0/2/3):-1:-1:-1/vtsp_allocate_cdb:
CDB=0x3C3B20D0
107583: *Jan 26 00:13:42.990 Mexico: //-1/xxxxxxxxxxxx/VTSP:(0/2/3):-1:-1:-1/vtsp_do_call_setup_ind:
Event=E_TSP_SETUP_IND
Progress Indication=3, CarrierIDCode=, Info Trans Capability=144, Source Carrier ID=, tg_label_flag=0
107584: *Jan 26 00:13:42.990 Mexico: //-1/C8D1DD468617/VTSP:(0/2/3):-1:-1:-1/vtsp_do_normal_call_setup_ind:
107585: *Jan 26 00:13:42.990 Mexico: //-1/C8D1DD468617/VTSP:(0/2/3):-1:-1:-1/vtsp_timer:
Timer Start Time=13286374, Timer Value=180000(ms)
107586: *Jan 26 00:13:42.990 Mexico: //-1/C8D1DD468617/VTSP:(0/2/3):-1:-1:-1/vtsp_do_normal_call_setup_ind:
IC State Machine (ICSM) Added
107587: *Jan 26 00:13:42.990 Mexico: //-1/C8D1DD468617/VTSP:(0/2/3):-1:-1:-1/vtsp_insert_cdb:
107588: *Jan 26 00:13:42.994 Mexico: //-1/C8D1DD468617/VTSP:(0/2/3):-1:1:1/vtsp_dsm_opened_cb:
107589: *Jan 26 00:13:42.994 Mexico: //-1/C8D1DD468617/VTSP:(0/2/3):-1:1:1/vtsp_process_event:
[state:S_SETUP_IND_PEND, event:E_VTSP_DSM_OPEN_SUCCESS]
107590: *Jan 26 00:13:42.994 Mexico: //-1/C8D1DD468617/VTSP:(0/2/3):-1:1:1/act_setup_ind_pend_success:
107591: *Jan 26 00:13:42.994 Mexico: //-1/C8D1DD468617/VTSP:(0/2/3):-1:1:1/vtsp_realloc_cdb:
CDB=0x3C3B20D0
107592: *Jan 26 00:13:42.994 Mexico: //-1/C8D1DD468617/VTSP:(0/2/3):-1:1:1/vtsp_indicate_call:
107593: *Jan 26 00:13:42.994 Mexico: //6874/C8D1DD468617/VTSP:(0/2/3):-1:1:1/vtsp_insert_cdb:
107594: *Jan 26 00:13:42.994 Mexico: //6874/C8D1DD468617/VTSP:(0/2/3):-1:1:1/vtsp_timer:
Timer Start Time=13286374, Timer Value=180000(ms)
107595: *Jan 26 00:13:42.994 Mexico: [0/2/3] htsp_dsm_close_done
107596: *Jan 26 00:13:42.994 Mexico: htsp_process_event: [0/2/3, FXOLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]
107597: *Jan 26 00:13:42.994 Mexico: fxols_wait_setup_ack:
107598: *Jan 26 00:13:42.994 Mexico: [0/2/3] set signal state = 0xC timestamp = 0fxols_check_auto_call
107599: *Jan 26 00:13:42.998 Mexico: //6874/C8D1DD468617/VTSP:(0/2/3):-1:1:1/vtsp_process_event:
[state:S_SETUP_INDICATED, event:E_CC_PROCEEDING]
107600: *Jan 26 00:13:42.998 Mexico: //6874/C8D1DD468617/VTSP:(0/2/3):-1:1:1/act_proceeding:
Progress Indication=0
107601: *Jan 26 00:13:42.998 Mexico: //6874/C8D1DD468617/VTSP:(0/2/3):-1:1:1/vtsp_timer_stop:
Timer Stop Time=13286374
107602: *Jan 26 00:13:42.998 Mexico: htsp_process_event: [0/2/3, FXOLS_PROCEEDING, E_HTSP_PROCEEDING]fxols_offhook_proc
107603: *Jan 26 00:13:42.998 Mexico: htsp_timer - 120000 msec
107604: *Jan 26 00:13:42.998 Mexico: //6874/C8D1DD468617/VTSP:(0/2/3):-1:1:1/vtsp_process_event:
[state:S_PROCEEDING, event:E_CC_DISCONNECT]
107605: *Jan 26 00:13:42.998 Mexico: //6874/C8D1DD468617/VTSP:(0/2/3):-1:1:1/act_pre_con_disconnect:
Cause Value=28, Hairpin=FALSE
107606: *Jan 26 00:13:42.998 Mexico: //6874/C8D1DD468617/VTSP:(0/2/3):-1:1:1/vtsp_timer_stop:
Timer Stop Time=13286374
107607: *Jan 26 00:13:42.998 Mexico: //6874/C8D1DD468617/VTSP:(0/2/3):-1:1:1/vtsp_ring_noan_timer_stop:
Timer Stop Time=13286374
107608: *Jan 26 00:13:42.998 Mexico: //6874/C8D1DD468617/VTSP:(0/2/3):-1:1:1/act_pre_con_disconnect:
[Number Unobtainable]-Tone Played In Direction [Network]
107609: *Jan 26 00:13:42.998 Mexico: //6874/C8D1DD468617/VTSP:(0/2/3):-1:1:1/vtsp_timer:
Timer Start Time=13286374, Timer Value=2000(ms)
107610: *Jan 26 00:13:42.998 Mexico: htsp_pre_connect_disconnect, cdb = 3C3B20D0 cause = 1C

107611: *Jan 26 00:13:42.998 Mexico: //6874/C8D1DD468617/VTSP:(0/2/3):-1:1:1/act_pre_con_disconnect:
Tone=Number Unobtainable, Tone Timeout=2(s), Progress Indication Sent=0
107612: *Jan 26 00:13:42.998 Mexico: htsp_process_event: [0/2/3, FXOLS_PROCEEDING, E_HTSP_PRE_CONN_DISC]
107613: *Jan 26 00:13:43.318 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x6 timestamp=22211 systime=13286406
107614: *Jan 26 00:13:43.318 Mexico: htsp_process_event: [0/2/3, FXOLS_OFFHOOK, E_DSP_SIG_0110]
107615: *Jan 26 00:13:43.318 Mexico: htsp_timer_stop2
107616: *Jan 26 00:13:44.546 Mexico: //6874/C8D1DD468617/VTSP:(0/2/3):-1:1:1/vtsp_get_levels:
CALL_ERROR_INFORMATIONAL; DSP Timeout
107617: *Jan 26 00:13:44.998 Mexico: //6874/C8D1DD468617/VTSP:(0/2/3):-1:1:1/vtsp_process_event:
[state:S_WAIT_RELEASE_NC, event:E_TIMER]
107618: *Jan 26 00:13:44.998 Mexico: //6874/C8D1DD468617/VTSP:(0/2/3):-1:1:1/act_pre_con_disc_rel:
107619: *Jan 26 00:13:44.998 Mexico: //6874/C8D1DD468617/VTSP:(0/2/3):-1:1:1/act_pre_con_disc_rel:
Cause Value=28
107620: *Jan 26 00:13:44.998 Mexico: htsp_process_event: [0/2/3, FXOLS_OFFHOOK, E_HTSP_RELEASE_REQ]fxols_offhook_release
107621: *Jan 26 00:13:44.998 Mexico: htsp_timer_stop
107622: *Jan 26 00:13:44.998 Mexico: htsp_timer_stop2
107623: *Jan 26 00:13:44.998 Mexico: htsp_timer_stop3
107624: *Jan 26 00:13:44.998 Mexico: [0/2/3] set signal state = 0x4 timestamp = 0
107625: *Jan 26 00:13:44.998 Mexico: htsp_timer - 2000 msec
107626: *Jan 26 00:13:44.998 Mexico: //6874/C8D1DD468617/VTSP:(0/2/3):-1:1:1/vtsp_process_event:
[state:S_WAIT_RELEASE_RESP, event:E_TSP_DISCONNECT_CONF]
107627: *Jan 26 00:13:44.998 Mexico: //6874/C8D1DD468617/VTSP:(0/2/3):-1:1:1/act_wrelease_release:
107628: *Jan 26 00:13:44.998 Mexico: //6874/C8D1DD468617/VTSP:(0/2/3):-1:1:1/vtsp_play_busy_timer_stop:
Timer Stop Time=13286574
107629: *Jan 26 00:13:44.998 Mexico: //6874/C8D1DD468617/VTSP:(0/2/3):-1:1:1/vtsp_timer_stop:
Timer Stop Time=13286574
107630: *Jan 26 00:13:44.998 Mexico: //6874/C8D1DD468617/VTSP:(0/2/3):-1:1:1/vtsp_do_call_history:
107631: *Jan 26 00:13:44.998 Mexico: //6874/C8D1DD468617/VTSP:(0/2/3):-1:1:1/vtsp_do_call_history:
Coder Rate=-1
107632: *Jan 26 00:13:44.998 Mexico: //6874/C8D1DD468617/VTSP:(0/2/3):-1:1:1/vtsp_is_valid_dsm_handle:
DMGR=0x42731810, VTSP CDB=0x3C3B20D0
107633: *Jan 26 00:13:44.998 Mexico: //6874/C8D1DD468617/VTSP:(0/2/3):-1:-1:-1/vtsp_dsm_closed_cb:
107634: *Jan 26 00:13:44.998 Mexico: //6874/C8D1DD468617/VTSP:(0/2/3):-1:-1:-1/vtsp_process_event:
[state:S_CLOSE_DSPRM, event:E_VTSP_DSM_CLOSE_COMPLETE]
107635: *Jan 26 00:13:44.998 Mexico: //6874/C8D1DD468617/VTSP:(0/2/3):-1:-1:-1/act_terminate:
107636: *Jan 26 00:13:44.998 Mexico: //6874/C8D1DD468617/VTSP:(0/2/3):-1:-1:-1/vtsp_timer_stop:
Timer Stop Time=13286574
107637: *Jan 26 00:13:44.998 Mexico: //-1/C8D1DD468617/VTSP:(0/2/3):-1:-1:-1/vtsp_free_cdb:
CDB=0x3C3B20D0
107638: *Jan 26 00:13:45.270 Mexico: htsp_dsp_message: SEND_SIG_STATUS: state=0x6 timestamp=24162 systime=13286602
107639: *Jan 26 00:13:45.270 Mexico: htsp_process_event: [0/2/3, FXOLS_GUARD_OUT, E_DSP_SIG_0110]
107640: *Jan 26 00:13:46.998 Mexico: htsp_process_event: [0/2/3, FXOLS_GUARD_OUT, E_HTSP_EVENT_TIMER]fxols_guard_out_timeout
107641: *Jan 26 00:13:46.998 Mexico: htsp_dsp_message: RESP_SIG_STATUS: state=0x4 timestamp=0 systime=13286774
107642: *Jan 26 00:13:46.998 Mexico: htsp_process_event: [0/2/3, FXOLS_ONHOOK, E_DSP_SIG_0100]
107643: *Jan 26 00:14:14.894 Mexico: %VOICE_IEC-3-GW: Application Framework Core: Internal Error (Toll fraud call rejected): IEC=1.1.228.3.31.0 on callID 6875 GUID=F297C8D60B55E66341D278EDB56F6B24
107644: *Jan 26 00:15:28.702 Mexico: %VOICE_IEC-3-GW: Application Framework Core: Internal Error (Toll fraud call rejected): IEC=1.1.228.3.31.0 on callID 6876 GUID=E61D225595983FAA9B50F255AC80FF18
GNP_GATEWAY#

[Nadeem Ahmed · Accepted solution]

dial-peer voice 507 pots
description DIDs Avaya to Cisco Unified Communicatios Manager Express
translation-profile incoming DID2
destination-pattern <dialed number which you are dialing>=====>
incoming called-number .
direct-inward-dial
port 0/2/3

and on voice port add connection plar with destined

voice-port 0/2/3

connection plar <the number which is being sent from Avaya>

make this change and re-collect the same debugs

[fdamian01]

Hi

You are right a connection PLAR longer works.

I did not know that FXO not have any ani is received only in digital trunks.

thanks for the help

Regards.