IVR Server Not answering Calls

Joel Jackson · ‎04-26-2018

We have a few servers that have an IVR application that connects to a voice gateway via CAS T1s. I'm in the process of retiring a 2811 gateway and this is being moved over to our 4451. We are running CUCM 10.5 and the T1 is registered via MGCP. I've got the configuration on the new router and everything looks correct to me. When I call into the server while it's connected to the new router the call just hangs up instantly. A "debug vpm sig" shows the following.

Apr 26 16:58:13.915: htsp_timer_stop3 htsp_setup_req
Apr 26 16:58:13.916:  Orig called num:49991
Apr 26 16:58:13.916: htsp_process_event: [0/2/0:1(24), EM_ONHOOK, E_HTSP_SETUP_REQ]em_onhook_setup
Apr 26 16:58:13.916: em_offhook (0)vnm_dsp_set_sig_state:[recEive and transMit0/2/0:1(24)] set signal state = 0x8
Apr 26 16:58:13.916: htsp_call_bridged invoked
Apr 26 16:58:13.917: htsp_process_event: [0/2/0:1(24), EM_BRANCH, EM_EVENT_WINK]
Apr 26 16:58:13.917: em_start_timer: 550 ms
Apr 26 16:58:13.917: htsp_timer - 550 msec
Apr 26 16:58:13.918: htsp_process_event: [0/2/0:1(24), EM_WAIT_WINKUP, E_HTSP_VOICE_CUT_THROUGH]
Apr 26 16:58:13.918: htsp_process_event: [0/2/0:1(24), EM_WAIT_WINKUP, E_HTSP_VOICE_CUT_THROUGH]
Apr 26 16:58:14.467: htsp_process_event: [0/2/0:1(24), EM_WAIT_WINKUP, E_HTSP_EVENT_TIMER]em_wink_timeout
Apr 26 16:58:14.467: em_stop_timers
Apr 26 16:58:14.467: htsp_timer_stop2 em_onhook (0)vnm_dsp_set_sig_state:[recEive and transMit0/2/0:1(24)] set signal state = 0x0
Apr 26 16:58:14.467: em_start_timer: 400 ms
Apr 26 16:58:14.467: htsp_timer - 400 msec
Apr 26 16:58:14.497: htsp_process_event: [0/2/0:1(24), EM_GUARD_ALL, E_HTSP_RELEASE_REQ]
Apr 26 16:58:14.868: htsp_process_event: [0/2/0:1(24), EM_GUARD_ALL_RLS_REQ, E_HTSP_EVENT_TIMER]em_guard_all_timer
Apr 26 16:58:14.868: em_stop_timers
Apr 26 16:58:14.868: htsp_timer_stop
Apr 26 16:58:14.868: em_stop_timers
Apr 26 16:58:14.868: htsp_timer_stop2
Apr 26 16:58:14.868: em_start_timer: 3000 ms
Apr 26 16:58:14.868: htsp_timer - 3000 msec
Apr 26 16:58:14.887: htsp_dsp_message: RESP_SIG_STATUS: state=0x0 timestamp=0 systime=513059143
Apr 26 16:58:14.887: htsp_process_event: [0/2/0:1(24), EM_PARK, E_DSP_SIG_0000]em_park_onhook
Apr 26 16:58:14.888: htsp_timer_stop
Apr 26 16:58:14.888: htsp_timer_stop2 htsp_report_onhook_sig

There is a em_wink_timeout happening and I'm not sure why. When connecting it back to the old GW it works. The configs are similar. It seems like a clocking issue but I'm not exactly sure what is going on. Was hoping to get some insight into this.

Joel Jackson · ‎04-27-2018

Bump...

R0g22 · ‎04-28-2018

Can you add your config here ? What is the CAS circuit configured as, wink start ? Timeout usually occurs when when the router does not get a response for a wink.

Joel Jackson · ‎04-30-2018

version 15.5
service timestamps debug datetime msec localtime
service timestamps log datetime msec localtime
no platform punt-keepalive disable-kernel-core
platform hardware throughput level 2000000
!

boot-start-marker
boot system bootflash:isr4400-universalk9.03.16.05.S.155-3.S5-ext.SPA.bin
boot-end-marker
!
!
vrf definition Mgmt-intf
 !
 address-family ipv4
 exit-address-family
 !
 address-family ipv6
 exit-address-family
!
card type t1 0 2
logging buffered 1000000
!
aaa new-model
!
!
aaa authentication login default group tacacs+ local
aaa authentication login console local
aaa authentication enable default group tacacs+ enable
aaa authorization exec default group tacacs+ local 
!
!
!
!
!
!
aaa session-id common
clock timezone EDT -5 0
clock summer-time EDT recurring
!
!
!
ip name-server 

ip domain name domain.local
ip dhcp excluded-address 
ip dhcp excluded-address 
!

!
!
!
!
!
!
!
subscriber templating
multilink bundle-name authenticated
!
!
!
!
isdn switch-type primary-ni
!
!
!
!
!
voice service voip
 ip address trusted list
  ipv4 IP
  ipv4 IP
 allow-connections h323 to h323
 allow-connections h323 to sip
 allow-connections sip to h323
 allow-connections sip to sip
 fax protocol t38 version 0 ls-redundancy 0 hs-redundancy 0 fallback none
!
voice class codec 3
 codec preference 1 g711ulaw
 codec preference 2 g729r8
 codec preference 3 g729br8
!
!
!
!
!
voice register global
 default mode
 no allow-hash-in-dn
!
!
!
!
!
!
voice-card 0/1
 no watchdog
!
voice-card 0/2
 dsp services dspfarm
 no watchdog
!
license udi pid ISR4451-X/K9 sn SERIAL
license accept end user agreement
!
spanning-tree extend system-id
!

redundancy
 mode none
!
controller T1 0/2/0
 framing sf
 clock source network
 linecode ami
 cablelength short 110
 ds0-group 1 timeslots 1-24 type e&m-wink-start
!
controller T1 0/2/1
 framing esf
 clock source internal
 linecode b8zs
 cablelength long 0db
!
!
!
!
!
!
!
!
interface GigabitEthernet0/0/0
 ip address IP
 negotiation auto
!
interface GigabitEthernet0/0/1
 no ip address
 negotiation auto
!
interface GigabitEthernet0/0/2
 no ip address
 shutdown
 negotiation auto
!
interface GigabitEthernet0/0/3
 no ip address
 shutdown
 negotiation auto
!
interface Service-Engine0/1/0
!
interface Service-Engine0/2/0
 no ip address
!
interface GigabitEthernet0
 vrf forwarding Mgmt-intf
 no ip address
 shutdown
 negotiation auto
!
!
router eigrp 1
 network 10.0.0.0
 offset-list backup_routes in 50 GigabitEthernet0/0/0 
 passive-interface default
 no passive-interface GigabitEthernet0/0/0
 no passive-interface GigabitEthernet0/0/1.31
!
ip forward-protocol nd
no ip http server
no ip http secure-server
ip tftp source-interface GigabitEthernet0/0/1.3
ip ssh version 2
ip ssh server algorithm mac hmac-sha1
ip ssh server algorithm encryption aes256-ctr
!
!
ip access-list standard backup_route
ip access-list standard backup_routes
 permit any
!
!
!
control-plane
!
!
voice-port 0/2/0:1
 echo-cancel coverage 64
!
voice-port 0/1/0
 timing hookflash-out 50
 timing guard-out 1000
 description 757-351-2673
!
voice-port 0/1/1
 timing hookflash-out 50
 timing guard-out 1000
 description NOT IN USE
 !
 !
 !
 !
!
mgcp
mgcp call-agent hostname 2427 service-type mgcp version 0.1
mgcp dtmf-relay voip codec all mode out-of-band
mgcp rtp unreachable timeout 1000 action notify
mgcp modem passthrough voip mode nse
mgcp package-capability rtp-package
mgcp package-capability sst-package
mgcp package-capability pre-package
no mgcp package-capability res-package
no mgcp package-capability fxr-package
no mgcp timer receive-rtcp
mgcp sdp simple
mgcp fax t38 inhibit
mgcp rtp payload-type g726r16 static
mgcp bind control source-interface GigabitEthernet0/0/1.3
mgcp bind media source-interface GigabitEthernet0/0/1.3
mgcp behavior rsip-range tgcp-only
mgcp behavior comedia-role none
mgcp behavior comedia-check-media-src disable
mgcp behavior comedia-sdp-force disable
!
mgcp profile default
!
sccp local GigabitEthernet0/0/1.3
sccp ccm IP identifier 1 version 7.0 
sccp ccm IP identifier 2 version 7.0 
sccp ccm IP identifier 3 version 7.0 
sccp ccm IP identifier 4 version 7.0 
sccp
!
sccp ccm group 1
 bind interface GigabitEthernet0/0/1.3
 associate ccm 2 priority 1
 associate ccm 1 priority 2
 associate ccm 3 priority 3
 associate ccm 4 priority 4
!
ccm-manager music-on-hold
!
ccm-manager fallback-mgcp 
ccm-manager redundant-host hostname hostname
ccm-manager mgcp
no ccm-manager fax protocol cisco
ccm-manager config server IPs
ccm-manager config
!
telephony-service
 max-ephones 50
 max-dn 50
 max-conferences 8 gain -6
 transfer-system full-consult
!
!
dial-peer voice 100 pots
 service mgcpapp
 port 0/1/0
!
dial-peer voice 999010 pots
 service mgcpapp
 port 0/1/0
!
dial-peer voice 999011 pots
 service mgcpapp
 port 0/1/1
!
dial-peer voice 999020991 pots
 service mgcpapp
 port 0/2/0:1
!
dial-peer voice 120 pots
 port 0/2/0:1
!
!
!
line con 0
 privilege level 15
 stopbits 1
line aux 0
 stopbits 1
line vty 0 4
 privilege level 15
 transport input ssh
line vty 5 15
 privilege level 15
 transport input ssh
!
network-clock synchronization automatic
ntp server IP
!
end

It is e&m-wink-start. If I connect the server back to the old gateway it answers as expected.

R0g22 · ‎05-02-2018

Collect the following for a test call please -

debug mgcp packet
debug mgcp error
debug voip vtsp all
debug vpm signal
debug voice ccapi inout

Joel Jackson · ‎05-02-2018

=~=~=~=~=~=~=~=~=~=~=~= PuTTY log 2018.05.02 10:26:50 =~=~=~=~=~=~=~=~=~=~=~=

May 2 10:26:38.216: MGCP Packet sent to [IP]12:2427--->
NTFY 520787460 *@RV-4451-VA-CLEV.domain.com MGCP 0.1
X: 0
O:
<---

May 2 10:26:38.219: MGCP Packet received from [IP]12:2427--->
200 520787460
<---

RV-4451-VA-CLEV#term mon
May 2 10:26:53.216: MGCP Packet sent to [IP]12:2427--->
NTFY 520787461 *@RV-4451-VA-CLEV.domain.com MGCP 0.1
X: 0
O:
<---

May 2 10:26:53.218: MGCP Packet received from [IP]12:2427--->
200 520787461
<---
debug mgcp packets
RV-4451-VA-CLEV#debug mgcp packets
RV-4451-VA-CLEV#debug mgcp packets
Media Gateway Control Protocol packets debugging for all endpoints is on
RV-4451-VA-CLEV#
May 2 10:27:04.165: MGCP Packet received from [IP]12:2427--->
CRCX 812899 S0/SU2/DS1-0/24@RV-4451-VA-CLEV.domain.com MGCP 0.1
C: A000000005795848000000F5
X: 17
L: p:20, a:PCMU, s:off, t:00
M: recvonly
R: DT/oc, DT/of
S: DT/sup(addr(4,9,9,9,1))
Q: process,loop
<---

May 2 10:27:04.167: MGCP Packet sent to [IP]12:2427--->
200 812899 OK
I: 8

v=0
c=IN IP4 10.3.3.254
m=audio 8256 RTP/AVP 0 100
a=rtpmap:100 X-NSE/8000
a=fmtp:100 192-194
<---

May 2 10:27:04.716: MGCP Packet sent to [IP]12:2427--->
NTFY 520787462 S0/SU2/DS1-0/24@RV-4451-VA-CLEV.domain.com MGCP 0.1
N: ca@[IP]12:2427
X: 17
O: DT/of(dt/sup)
<---

May 2 10:27:04.719: MGCP Packet received from [IP]12:2427--->
200 520787462
<---

May 2 10:27:04.719: MGCP Packet received from [IP]12:2427--->
DLCX 812900 S0/SU2/DS1-0/24@RV-4451-VA-CLEV.domain.com MGCP 0.1
C: A000000005795848000000F5
I: 8
X: 17
<---

May 2 10:27:04.721: MGCP Packet sent to [IP]12:2427--->
250 812900 OK
P: PS=0, OS=0, PR=0, OR=0, PL=0, JI=0, LA=0
<---

May 2 10:27:04.724: MGCP Packet received from [IP]12:2427--->
RQNT 812901 S0/SU2/DS1-0/24@RV-4451-VA-CLEV.domain.com MGCP 0.1
X: 17
R: DT/sup, D/[0-9ABCD*#]
S: DT/rlc
Q: process,loop
<---

May 2 10:27:05.133: MGCP Packet sent to [IP]12:2427--->
200 812901 OK
<---

May 2 10:27:05.133: MGCP Packet sent to [IP]12:2427--->
NTFY 520787463 S0/SU2/DS1-0/24@RV-4451-VA-CLEV.domain.com MGCP 0.1
N: ca@[IP]12:2427
X: 17
O: DT/rlc
<---

May 2 10:27:05.136: MGCP Packet received from [IP]12:2427--->
200 520787463
<---

May 2 10:27:05.136: MGCP Packet received from [IP]12:2427--->
RQNT 812902 S0/SU2/DS1-0/24@RV-4451-VA-CLEV.domain.com MGCP 0.1
X: 17
R: DT/sup, D/[0-9ABCD*#]
Q: process,loop
<---

May 2 10:27:05.136: MGCP Packet sent to [IP]12:2427--->
200 812902 OK
<---
q
RV-4451-VA-CLEV#
RV-4451-VA-CLEV#u all
All possible debugging has been turned off
RV-4451-VA-CLEV#debug mgcp error
Media Gateway Control Protocol errors debugging for all endpoints is on
RV-4451-VA-CLEV#
May 2 10:27:24.898: //545/C47924098090/MGCP|S0/SU2/DS1-0/24|-1|-1/<VOICE>/process_start_signal(4122):[lvl=2]process_start_signal(): FAIL with rc: 8, need to reject the whole list
May 2 10:27:25.451: //-1/xxxxxxxxxxxx/MGCP/mgcp_mp_get_not_entity(830):[lvl=2]Invalid parameter (pkt 0x7F8D62287660 pkt->mgcp_parm_lines 0x0)
May 2 10:27:25.857: //545/C47924098090/MGCP|S0/SU2/DS1-0/24|-1|-1/<VOICE>/mgcp_cas_oc_conn_call_feature(3285):[lvl=2]unexpected call feature(6)
May 2 10:27:25.861: //-1/xxxxxxxxxxxx/MGCP/mgcp_mp_get_not_entity(830):[lvl=2]Invalid parameter (pkt 0x7F8D622877C8 pkt->mgcp_parm_lines 0x0)
RV-4451-VA-CLEV#
RV-4451-VA-CLEV#
RV-4451-VA-CLEV#u all
All possible debugging has been turned off
RV-4451-VA-CLEV#debug voip vtsp all
RV-4451-VA-CLEV#debug voip vtsp all
voip vtsp all debugging is on

RV-4451-VA-CLEV#
RV-4451-VA-CLEV#
RV-4451-VA-CLEV#
RV-4451-VA-CLEV#
RV-4451-VA-CLEV#
RV-4451-VA-CLEV#
May 2 10:27:59.041: //-1/xxxxxxxxxxxx/VTSP:(0/2/0:1):-1:-1:-1/vtsp_allocate_cdb:
CDB=0x7F8D62297F30
May 2 10:27:59.041: //-1/xxxxxxxxxxxx/VTSP:(0/2/0:1):-1:-1:-1/vtsp_insert_cdb:
May 2 10:27:59.041: //-1/xxxxxxxxxxxx/VTSP:(0/2/0:1):-1:-1:-1/vtsp_process_event:
[state:INVALID STATE MACHINE, event:E_CC_SETUP_REQ]
May 2 10:27:59.041: //547/D8D342658091/VTSP:(0/2/0:1):-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 10:27:59.041: //547/D8D342658091/VTSP:(0/2/0:1):-1:-1:-1/vtsp_do_call_setup_req:
May 2 10:27:59.041: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_opened_cb:
May 2 10:27:59.041: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_process_event:
[state:S_SETUP_REQ_PEND, event:E_VTSP_DSM_OPEN_SUCCESS]
May 2 10:27:59.041: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/act_setup_req_pend_succ:
May 2 10:27:59.042: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_request_call:
Mode=9, Peer=0
May 2 10:27:59.042: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_create_call_active_on_setup_req:
Target Carrier ID=
May 2 10:27:59.042: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_create_call_active_on_setup_req:
Source Carrier ID=
May 2 10:27:59.042: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_request_call:
Progress Indication=0, Info Trans Capability=0
Calling Number=, TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed
Called Number=49991, TON=Unknown, NPI=Unknown
May 2 10:27:59.042: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_process_event:
[state:S_SETUP_REQUEST, event:E_TSP_PROCEEDING]
May 2 10:27:59.042: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/act_setup_pend_proceeding:
May 2 10:27:59.042: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_timer:
Timer Start Time=562557558, Timer Value=25000(ms)
May 2 10:27:59.042: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/act_setup_pend_proceeding:
Peer=0, Progress Indication=0, Return Code=2
May 2 10:27:59.042: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_report_digit_control:
May 2 10:27:59.042: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_report_digit_control:
Digit Reporting=TRUE
May 2 10:27:59.042: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_bridge_check_cb:
May 2 10:27:59.042: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_bridge_check_cb:exit@1496
May 2 10:27:59.042: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_bridge_status_cb:
May 2 10:27:59.042: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_save_fax_config:
May 2 10:27:59.042: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_save_fax_config:
Fax Relay=DISABLED - MGCP Application
Primary Fax Protocol=IGNORE_FAX_RELAY, Fallback Fax Protocol=IGNORE_FAX_RELAY
Fax Relay CM Suppression :=ENABLED, Fax Relay ANS Suppression :=DISABLED
Fax Parameters Set By=MGCP Call Type
May 2 10:27:59.042: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_set_fax_feat_param:
May 2 10:27:59.042: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_save_tty_config:
May 2 10:27:59.042: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_save_tty_config:
Save TTY configuration
May 2 10:27:59.042: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_set_tty_feat_param:
May 2 10:27:59.042: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_set_tty_feat_param:
Set TTY feat parameters
May 2 10:27:59.042: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_process_event:
[state:S_NULL, event:E_CC_DO_CAPS_IND]
May 2 10:27:59.042: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_peer_event_cb:
Event=E_DSM_CC_CAPS_IND
May 2 10:27:59.042: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_process_event:
[state:S_NULL, event:E_CC_CAPS_IND]
May 2 10:27:59.042: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/act_setup_req_pend_defer:
Event=67
May 2 10:27:59.043: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_opened_cb:
May 2 10:27:59.043: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_call_mod_done_cb:
May 2 10:27:59.044: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_save_fax_config:
May 2 10:27:59.044: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_save_fax_config:
Fax Relay=DISABLED - MGCP Application
Primary Fax Protocol=IGNORE_FAX_RELAY, Fallback Fax Protocol=IGNORE_FAX_RELAY
Fax Relay CM Suppression :=ENABLED, Fax Relay ANS Suppression :=DISABLED
Fax Parameters Set By=MGCP Call Type
May 2 10:27:59.044: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_set_fax_feat_param:
May 2 10:27:59.044: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_process_event:
[state:S_NULL, event:E_VTSP_DSM_OPEN_SUCCESS]
May 2 10:27:59.044: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/act_setup_req_wait_pend_success:
Event=76
May 2 10:27:59.044: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_timer_stop:
Timer Stop Time=562557559
May 2 10:27:59.044: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_peer_event_cb:
Event=E_DSM_CC_CAPS_ACK
May 2 10:27:59.044: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_feature_notify_cb:
Feature ID=0, Feature Status=1
May 2 10:27:59.044: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_reactivate_ringback:
May 2 10:27:59.044: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_reactivate_ringback:exit@1287
May 2 10:27:59.044: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_fpi_event_cb:
Event=E_DSMP_FPI_ENABLE_TDM_RTCP
May 2 10:27:59.593: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_process_event:
[state:S_SETUP_REQ_PROC, event:E_TSP_DISCONNECT_IND]
May 2 10:27:59.593: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/act_setup_pend_release_ind:
Cause Value=44
May 2 10:27:59.593: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_ring_noan_timer_stop:
Timer Stop Time=562557614
May 2 10:27:59.593: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_cc_call_disconnected:
May 2 10:27:59.593: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_cc_call_disconnected:
Cause Value=44
May 2 10:27:59.593: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_set_release_source:
Release Direction=PSTN, Release Source=Called Party-PSTN
May 2 10:27:59.593: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/act_setup_pend_release_ind:
Peer=0
May 2 10:27:59.593: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_call_disconnect:
[Out Of Service]-Tone Played In Direction [Both]
May 2 10:27:59.594: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_process_event:
[state:S_WAIT_HOST_DISC, event:E_CC_DISCONNECT]
May 2 10:27:59.594: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/act_host_disc_cleanup:
dsm_indicate_error=0, short_cleardown_timeout=1, Mode=9
May 2 10:27:59.594: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_save_fax_config:
May 2 10:27:59.594: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_save_fax_config:
Fax Relay=DISABLED - MGCP Application
Primary Fax Protocol=IGNORE_FAX_RELAY, Fallback Fax Protocol=IGNORE_FAX_RELAY
Fax Relay CM Suppression :=ENABLED, Fax Relay ANS Suppression :=DISABLED
Fax Parameters Set By=MGCP Call Type
May 2 10:27:59.594: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_set_fax_feat_param:
May 2 10:27:59.594: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/act_host_disc_cleanup:
Exit State=16
May 2 10:27:59.597: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_fpi_event_cb:
Event=E_DSMP_FPI_DISABLE_TDM_RTCP
May 2 10:27:59.597: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_bridge_status_cb:
May 2 10:27:59.618: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_get_levels_done_cb:
May 2 10:27:59.647: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_process_event:
[state:S_WAIT_STATS, event:E_VTSP_DSM_STATS_COMPLETE]
May 2 10:27:59.647: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/act_dsm_dsp_stats_complete:
May 2 10:27:59.647: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_timer:
Timer Start Time=562557619, Timer Value=60000(ms)
May 2 10:28:00.010: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_process_event:
[state:S_WAIT_RELEASE, event:E_TSP_CALL_FEATURE_IND]
May 2 10:28:00.010: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/act_call_feature_ind:
Feature Type=6
May 2 10:28:00.010: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_process_event:
[state:S_WAIT_RELEASE, event:E_TSP_DISCONNECT_CONF]
May 2 10:28:00.010: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/act_wrelease_release:
May 2 10:28:00.010: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_play_busy_timer_stop:
Timer Stop Time=562557655
May 2 10:28:00.010: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_timer_stop:
Timer Stop Time=562557655
May 2 10:28:00.010: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_do_call_history:
May 2 10:28:00.010: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_do_call_history:
Coder Rate=5
May 2 10:28:00.010: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_is_valid_dsm_handle:
DMGR=0x7F8D627A7760, VTSP CDB=0x7F8D62297F30
May 2 10:28:00.011: //547/D8D342658091/VTSP:(0/2/0:1):-1:-1:-1/vtsp_dsm_closed_cb:
May 2 10:28:00.011: //547/D8D342658091/VTSP:(0/2/0:1):-1:-1:-1/vtsp_process_event:
[state:S_CLOSE_DSPRM, event:E_VTSP_DSM_CLOSE_COMPLETE]
May 2 10:28:00.011: //547/D8D342658091/VTSP:(0/2/0:1):-1:-1:-1/act_terminate:
May 2 10:28:00.011: //547/D8D342658091/VTSP:(0/2/0:1):-1:-1:-1/vtsp_timer_stop:
Timer Stop Time=562557655
May 2 10:28:00.012: //-1/D8D342658091/VTSP:(0/2/0:1):-1:-1:-1/vtsp_free_cdb:
CDB=0x7F8D62297F30
RV-4451-VA-CLEV#
RV-4451-VA-CLEV#
RV-4451-VA-CLEV#
RV-4451-VA-CLEV#
RV-4451-VA-CLEV#
RV-4451-VA-CLEV#
RV-4451-VA-CLEV#u all
All possible debugging has been turned off
RV-4451-VA-CLEV#debug vpm sig
RV-4451-VA-CLEV#debug vpm signal
Voice Port Module signaling debugging is enabled
RV-4451-VA-CLEV#
May 2 10:28:22.520: htsp_timer_stop3 htsp_setup_req
May 2 10:28:22.520: Orig called num:49991
May 2 10:28:22.521: htsp_process_event: [0/2/0:1(24), EM_ONHOOK, E_HTSP_SETUP_REQ]em_onhook_setup
May 2 10:28:22.521: em_offhook (0)vnm_dsp_set_sig_state:[recEive and transMit0/2/0:1(24)] set signal state = 0x8
May 2 10:28:22.521: htsp_call_bridged invoked
May 2 10:28:22.521: htsp_process_event: [0/2/0:1(24), EM_BRANCH, EM_EVENT_WINK]
May 2 10:28:22.521: em_start_timer: 550 ms
May 2 10:28:22.521: htsp_timer - 550 msec
May 2 10:28:22.522: htsp_process_event: [0/2/0:1(24), EM_WAIT_WINKUP, E_HTSP_VOICE_CUT_THROUGH]
May 2 10:28:22.523: htsp_process_event: [0/2/0:1(24), EM_WAIT_WINKUP, E_HTSP_VOICE_CUT_THROUGH]
May 2 10:28:23.071: htsp_process_event: [0/2/0:1(24), EM_WAIT_WINKUP, E_HTSP_EVENT_TIMER]em_wink_timeout
May 2 10:28:23.071: em_stop_timers
May 2 10:28:23.071: htsp_timer_stop2 em_onhook (0)vnm_dsp_set_sig_state:[recEive and transMit0/2/0:1(24)] set signal state = 0x0
May 2 10:28:23.071: em_start_timer: 400 ms
May 2 10:28:23.071: htsp_timer - 400 msec
May 2 10:28:23.119: htsp_process_event: [0/2/0:1(24), EM_GUARD_ALL, E_HTSP_RELEASE_REQ]
May 2 10:28:23.472: htsp_process_event: [0/2/0:1(24), EM_GUARD_ALL_RLS_REQ, E_HTSP_EVENT_TIMER]em_guard_all_timer
May 2 10:28:23.472: em_stop_timers
May 2 10:28:23.472: htsp_timer_stop
May 2 10:28:23.472: em_stop_timers
May 2 10:28:23.472: htsp_timer_stop2
May 2 10:28:23.472: em_start_timer: 3000 ms
May 2 10:28:23.472: htsp_timer - 3000 msec
May 2 10:28:23.480: htsp_dsp_message: RESP_SIG_STATUS: state=0x0 timestamp=0 systime=562560002
May 2 10:28:23.480: htsp_process_event: [0/2/0:1(24), EM_PARK, E_DSP_SIG_0000]em_park_onhook
May 2 10:28:23.480: htsp_timer_stop
May 2 10:28:23.480: htsp_timer_stop2 htsp_report_onhook_sig
RV-4451-VA-CLEV#
RV-4451-VA-CLEV#
RV-4451-VA-CLEV#
RV-4451-VA-CLEV#
RV-4451-VA-CLEV#
RV-4451-VA-CLEV#u all
All possible debugging has been turned off
RV-4451-VA-CLEV#debug voic ce
RV-4451-VA-CLEV#debug voice ccap
RV-4451-VA-CLEV#debug voice ccapi inou
RV-4451-VA-CLEV#debug voice ccapi inout
voip ccapi inout debugging is on
RV-4451-VA-CLEV#
RV-4451-VA-CLEV#
RV-4451-VA-CLEV#
RV-4451-VA-CLEV#
May 2 10:28:41.846: //-1/xxxxxxxxxxxx/CCAPI/ccCallReportDigits:
(callID=0xFFFFFFFFFFFFFFFF, digit_event=0x0, enable=FALSE, consume=FALSE)
May 2 10:28:41.846: //-1/xxxxxxxxxxxx/CCAPI/ccIFCallSetupRequestPrivate:
Interface=0x7F8D4B274548, Interface Type=6, Destination=49991, Mode=0x9,
Call Params(Calling Number=,(Calling Name=)(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
Called Number=49991(TON=Unknown, NPI=Unknown), Calling Translated=FALSE,
Subscriber Type Str=, FinalDestinationFlag=FALSE, Outgoing Dial-peer=0, Call Count On=FALSE,
Source Trkgrp Route Label=, Target Trkgrp Route Label=, tg_label_flag=0, Application Call Id=A00000000579585d000000F5)
May 2 10:28:41.846: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

May 2 10:28:41.846: :cc_get_feature_vsa malloc success
May 2 10:28:41.846: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

May 2 10:28:41.846: cc_get_feature_vsa count is 1
May 2 10:28:41.846: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

May 2 10:28:41.846: :FEATURE_VSA attributes are: feature_name:0,feature_time:140244942088524,feature_id:267
May 2 10:28:41.846: //551/F256A00E8093/CCAPI/ccIFCallSetupRequestPrivate:
SPI Call Setup Request Is Success; Interface Type=6, FlowMode=1
May 2 10:28:41.846: //551/F256A00E8093/CCAPI/ccCallSetContext:
Context=0x7F8D624A2FC0
May 2 10:28:41.846: //-1/xxxxxxxxxxxx/CCAPI/ccIFCallSetupRequestPrivate:
Interface=0x7F8D50EB72A0, Interface Type=9, Destination=0.0.0.0, Mode=0x9,
Call Params(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=, FinalDestinationFlag=FALSE, Outgoing Dial-peer=0, Call Count On=TRUE,
Source Trkgrp Route Label=, Target Trkgrp Route Label=, tg_label_flag=0, Application Call Id=A00000000579585d000000F5)
May 2 10:28:41.846: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

May 2 10:28:41.846: :cc_get_feature_vsa malloc success
May 2 10:28:41.846: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

May 2 10:28:41.846: cc_get_feature_vsa count is 2
May 2 10:28:41.846: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

May 2 10:28:41.846: :FEATURE_VSA attributes are: feature_name:0,feature_time:140244942088300,feature_id:268
May 2 10:28:41.846: //552/F256A00E8093/CCAPI/ccIFCallSetupRequestPrivate:
SPI Call Setup Request Is Success; Interface Type=9, FlowMode=1
May 2 10:28:41.846: //552/F256A00E8093/CCAPI/ccCallSetContext:
Context=0x7F8D624A2EF8
May 2 10:28:41.846: //552/F256A00E8093/CCAPI/cc_api_call_connected:
Interface=0x7F8D50EB72A0, Data Bitmask=0x0, Progress Indication=NULL(0),
Connection Handle=0
May 2 10:28:41.846: //552/F256A00E8093/CCAPI/cc_api_call_connected:
Call Entry(Connected=TRUE, Responsed=TRUE, Retry Count=0)
May 2 10:28:41.847: //551/F256A00E8093/CCAPI/cc_api_call_proceeding:
Interface=0x7F8D4B274548, Progress Indication=NULL(0)
May 2 10:28:41.847: //551/F256A00E8093/CCAPI/ccCallModify:
Nominator=0x1000, Params=0x7F8D619352D4, Call Id=551
May 2 10:28:41.847: //551/F256A00E8093/CCAPI/ccCallReportDigits:
(callID=0x227, digit_event=0x1, enable=TRUE, consume=FALSE)
May 2 10:28:41.847: //551/F256A00E8093/CCAPI/ccCallReportDigits:
Enabled=TRUE, Call Id=551
May 2 10:28:41.847: //551/F256A00E8093/CCAPI/cc_api_call_report_digits_done:
(vdbPtr=0x7F8D4B274548, callID=0x227, disp=0, digit_event=0x1, enable=TRUE, consume=FALSE)
May 2 10:28:41.847: //551/F256A00E8093/CCAPI/cc_api_call_report_digits_done:
Enabled=TRUE, Disposition=0x0, Interface=0x7F8D4B274548, Call Id=551
May 2 10:28:41.847: //551/F256A00E8093/CCAPI/cc_api_call_report_digits_done:
Call Entry(Initial Digit Timeout=15000(ms), Inter Digit Timeout=10000(ms))
May 2 10:28:41.847: //551/F256A00E8093/CCAPI/ccConferenceCreate:
(confID=0xFFFFFFFFFFFFFFFF, callID1=0x227, gcid=0-0-0-0, tag=0x0)
May 2 10:28:41.847: //552/F256A00E8093/CCAPI/ccConferenceCreate:
(confID=0xFFFFFFFFFFFFFFFF, callID2=0x228, gcid=0-0-0-0, tag=0x0)
May 2 10:28:41.847: //551/F256A00E8093/CCAPI/ccConferenceCreate:
Conference Id=0xFFFFFFFFFFFFFFFF, Call Id1=551, Call Id2=552, Tag=0x0
May 2 10:28:41.847: //551/F256A00E8093/CCAPI/cc_api_bridge_done:
Conference Id=0x85, Source Interface=0x7F8D4B274548, Source Call Id=551,
Destination Call Id=552, Disposition=0x0, Tag=0xFFFFFFFFFFFFFFFF
May 2 10:28:41.847: //552/xxxxxxxxxxxx/CCAPI/cc_api_get_xcode_stream:

May 2 10:28:41.847: cc_api_get_xcode_stream : 4983
May 2 10:28:41.847: //552/xxxxxxxxxxxx/CCAPI/cc_api_ha_call_active_notify:

May 2 10:28:41.847: call_info mainst_callID:0x228, peer_callID:0x227, confID:0x85, spi_type:6, media_flo_thru:1,num_streams:1, swmtpmsp_present:0

May 2 10:28:41.847: //552/xxxxxxxxxxxx/CCAPI/cc_api_ha_call_active_notify:

May 2 10:28:41.847: stream[0]: callid:0x228, media_passthrough:0
May 2 10:28:41.847: //552/F256A00E8093/CCAPI/cc_api_bridge_done:
Conference Id=0x85, Source Interface=0x7F8D50EB72A0, Source Call Id=552,
Destination Call Id=551, Disposition=0x0, Tag=0x0
May 2 10:28:41.847: //551/F256A00E8093/CCAPI/cc_generic_bridge_done:
Conference Id=0x85, Source Interface=0x7F8D50EB72A0, Source Call Id=552,
Destination Call Id=551, Disposition=0x0, Tag=0x0
May 2 10:28:41.847: //551/F256A00E8093/CCAPI/ccConferenceCreate:
Call Entry(Conference Id=0x85, Destination Call Id=552)
May 2 10:28:41.847: //552/F256A00E8093/CCAPI/ccConferenceCreate:
Call Entry(Conference Id=0x85, Destination Call Id=551)
May 2 10:28:41.847: //551/F256A00E8093/CCAPI/ccConferenceCreate:

May 2 10:28:41.847: confID:0x85; callEntry1 callID1:0x227, type:6; callEntry2 callID2:0x228, type:9

May 2 10:28:41.847: //551/F256A00E8093/CCAPI/cc_api_caps_ind:
Destination Interface=0x7F8D50EB72A0, Destination Call Id=552, Source Call Id=551,
Caps(Codec=0x1, Fax Rate=0x1, Fax Version:=0, Vad=0x1,
Modem=0x2, Codec Bytes=20, Signal Type=3)
May 2 10:28:41.847: //551/F256A00E8093/CCAPI/cc_api_caps_ind:
Caps(Playout Mode=1, Playout Initial=60(ms), Playout Min=40(ms),
Playout Max=1000(ms), Fax Nom=300(ms))
May 2 10:28:41.847: //552/F256A00E8093/CCAPI/cc_api_caps_ind:
Destination Interface=0x7F8D4B274548, Destination Call Id=551, Source Call Id=552,
Caps(Codec=0x1, Fax Rate=0x2, Fax Version:=0, Vad=0x1,
Modem=0x2, Codec Bytes=160, Signal Type=2)
May 2 10:28:41.847: //552/F256A00E8093/CCAPI/cc_api_caps_ind:
Caps(Playout Mode=1, Playout Initial=60(ms), Playout Min=40(ms),
Playout Max=1000(ms), Fax Nom=300(ms))
May 2 10:28:41.847: //552/F256A00E8093/CCAPI/cc_api_caps_ack:
Destination Interface=0x7F8D4B274548, Destination Call Id=551, Source Call Id=552,
Caps(Codec=g711ulaw(0x1), Fax Rate=FAX_RATE_VOICE(0x2), Fax Version:=0, Vad=OFF(0x1),
Modem=ON(0x2), Codec Bytes=160, Signal Type=2, Seq Num Start=9659)
May 2 10:28:41.848: //551/F256A00E8093/CCAPI/cc_api_call_modify_done:
Result=0, Interface=0x7F8D4B274548, Call Id=551
May 2 10:28:41.848: //551/F256A00E8093/CCAPI/cc_api_caps_ack:
Destination Interface=0x7F8D50EB72A0, Destination Call Id=552, Source Call Id=551,
Caps(Codec=g711ulaw(0x1), Fax Rate=FAX_RATE_VOICE(0x2), Fax Version:=0, Vad=OFF(0x1),
Modem=ON(0x2), Codec Bytes=160, Signal Type=2, Seq Num Start=9659)
May 2 10:28:41.848: //551/F256A00E8093/CCAPI/cc_api_voice_mode_event:
Call Id=551
May 2 10:28:41.848: //551/F256A00E8093/CCAPI/cc_api_voice_mode_event:
Call Entry(Context=0x7F8D624A2FC0)
May 2 10:28:41.848: //551/F256A00E8093/CCAPI/cc_process_notify_bridge_done:
Conference Id=0x85, Call Id1=551, Call Id2=552
May 2 10:28:42.398: //551/F256A00E8093/CCAPI/cc_api_call_disconnected:
Cause Value=44, Interface=0x7F8D4B274548, Call Id=551
May 2 10:28:42.398: //551/F256A00E8093/CCAPI/cc_api_call_disconnected:
Call Entry(Responsed=TRUE, Cause Value=44, Retry Count=0)
May 2 10:28:42.398: //551/F256A00E8093/CCAPI/ccCallDisconnect:
Cause Value=16, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=44)
May 2 10:28:42.398: //551/F256A00E8093/CCAPI/ccCallDisconnect:
Cause Value=44, Call Entry(Responsed=TRUE, Cause Value=44)
May 2 10:28:42.401: //552/F256A00E8093/CCAPI/ccGetCallStatistics:
Call Stats=0x7F8D623A72E0, Call Id=552
May 2 10:28:42.401: //551/F256A00E8093/CCAPI/ccConferenceDestroy:
Conference Id=0x85, Tag=0x0
May 2 10:28:42.401: //551/F256A00E8093/CCAPI/ccConferenceDestroy:

May 2 10:28:42.401: confID:0x85; callEntry1 callID1:0x227, type:6; callEntry2 callID2:0x228, type:9

May 2 10:28:42.401: //551/F256A00E8093/CCAPI/cc_api_bridge_drop_done:
Conference Id=0x85, Source Interface=0x7F8D4B274548, Source Call Id=551,
Destination Call Id=552, Disposition=0x0, Tag=0x0
May 2 10:28:42.401: //552/xxxxxxxxxxxx/CCAPI/cc_api_get_xcode_stream:

May 2 10:28:42.401: cc_api_get_xcode_stream : 4983
May 2 10:28:42.401: //552/F256A00E8093/CCAPI/cc_api_bridge_drop_done:
Conference Id=0x85, Source Interface=0x7F8D50EB72A0, Source Call Id=552,
Destination Call Id=551, Disposition=0x0, Tag=0x0
May 2 10:28:42.401: //551/F256A00E8093/CCAPI/cc_generic_bridge_done:
Conference Id=0x85, Source Interface=0x7F8D50EB72A0, Source Call Id=552,
Destination Call Id=551, Disposition=0x0, Tag=0x0
May 2 10:28:42.401: //552/F256A00E8093/CCAPI/ccCallDisconnect:
Cause Value=16, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
May 2 10:28:42.401: //552/F256A00E8093/CCAPI/ccCallDisconnect:
Cause Value=16, Call Entry(Responsed=TRUE, Cause Value=16)
May 2 10:28:42.403: //552/F256A00E8093/CCAPI/cc_api_nw_stats:
Call Stats=0x7F8D57E003F8, Call Id=552
May 2 10:28:42.403: //552/F256A00E8093/CCAPI/cc_api_call_disconnect_done:
Disposition=0, Interface=0x7F8D50EB72A0, Tag=0x0, Call Id=552,
Call Entry(Disconnect Cause=16, Voice Class Cause Code=0, Retry Count=0)
May 2 10:28:42.403: //552/F256A00E8093/CCAPI/cc_api_call_disconnect_done:
Call Disconnect Event Sent
May 2 10:28:42.403: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

May 2 10:28:42.403: :cc_free_feature_vsa freeing 7F8D51F46860
May 2 10:28:42.403: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

May 2 10:28:42.403: vsacount in free is 1
May 2 10:28:42.815: //551/F256A00E8093/CCAPI/cc_api_call_feature:
Feature Type=6, Interface=0x7F8D4B274548, Call Id=551
May 2 10:28:42.817: //551/F256A00E8093/CCAPI/cc_api_call_disconnect_done:
Disposition=0, Interface=0x7F8D4B274548, Tag=0x0, Call Id=551,
Call Entry(Disconnect Cause=44, Voice Class Cause Code=0, Retry Count=0)
May 2 10:28:42.817: //551/F256A00E8093/CCAPI/cc_api_call_disconnect_done:
Call Disconnect Event Sent
May 2 10:28:42.817: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

May 2 10:28:42.817: :cc_free_feature_vsa freeing 7F8D51F46940
May 2 10:28:42.817: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

May 2 10:28:42.817: vsacount in free is 0

R0g22 · ‎05-02-2018

The logs were not taken correctly. You need to enable all of them at the same time and then make a test call. This is what I see from the logs though -

*/ CRCX from CUCM -

May 2 10:27:04.165: MGCP Packet received from [IP]12:2427--->
CRCX 812899 S0/SU2/DS1-0/24@RV-4451-VA-CLEV.domain.com MGCP 0.1
C: A000000005795848000000F5
X: 17
L: p:20, a:PCMU, s:off, t:00
M: recvonly
R: DT/oc, DT/of
S: DT/sup(addr(4,9,9,9,1)) >> call setup
Q: process,loop
<---

*/ GW Acks it -

May 2 10:27:04.167: MGCP Packet sent to [IP]12:2427--->
200 812899 OK
I: 8

v=0
c=IN IP4 10.3.3.254
m=audio 8256 RTP/AVP 0 100
a=rtpmap:100 X-NSE/8000
a=fmtp:100 192-194
<---

*/ GW drops the call immediately -

May 2 10:27:04.716: MGCP Packet sent to [IP]12:2427--->
NTFY 520787462 S0/SU2/DS1-0/24@RV-4451-VA-CLEV.domain.com MGCP 0.1
N: ca@[IP]12:2427
X: 17
O: DT/of(dt/sup) >>>> Operationa Fail
<---

*/ CUCM releases the call as well -

May 2 10:27:04.724: MGCP Packet received from [IP]12:2427--->
RQNT 812901 S0/SU2/DS1-0/24@RV-4451-VA-CLEV.domain.com MGCP 0.1
X: 17
R: DT/sup, D/[0-9ABCD*#]
S: DT/rlc >>>> release
Q: process,loop
<---

From the VTSP part, I see CV=44 which is circuit not available -

May 2 10:27:59.593: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_cc_call_disconnected:
Cause Value=44

May 2 10:27:59.593: //547/D8D342658091/VTSP:(0/2/0:1):-1:1:1/vtsp_call_disconnect:
[Out Of Service]-Tone Played In Direction [Both]

Take another log please. Need to see whether it is an MGCP stack issue or an issue at VTSP and/or port.

Joel Jackson · ‎05-02-2018

=~=~=~=~=~=~=~=~=~=~=~= PuTTY log 2018.05.02 11:37:14 =~=~=~=~=~=~=~=~=~=~=~=
term mon
RV-4451-VA-CLEV#
RV-4451-VA-CLEV#
RV-4451-VA-CLEV#
RV-4451-VA-CLEV#
RV-4451-VA-CLEV#
May  2 11:37:20.159: MGCP Packet sent to [IP]:2427--->
NTFY 520787752 *@RV-4451-VA-CLEV.domain.com MGCP 0.1
X: 0
O: 
<---

May  2 11:37:20.162: MGCP Packet received from [IP]:2427--->
200 520787752 
<---

May  2 11:37:24.936: MGCP Packet received from [IP]:2427--->
CRCX 818955 S0/SU2/DS1-0/24@RV-4451-VA-CLEV.domain.com MGCP 0.1
C: A000000005796251000000F5
X: 17
L: p:20, a:PCMU, s:off, t:00
M: recvonly
R: DT/oc, DT/of
S: DT/sup(addr(4,9,9,9,1))
Q: process,loop
<---

May  2 11:37:24.936: //-1/xxxxxxxxxxxx/CCAPI/ccCallReportDigits:
   (callID=0xFFFFFFFFFFFFFFFF, digit_event=0x0, enable=FALSE, consume=FALSE)
May  2 11:37:24.936: //-1/xxxxxxxxxxxx/CCAPI/ccIFCallSetupRequestPrivate:
   Interface=0x7F8D4B274548, Interface Type=6, Destination=49991, Mode=0x9,
   Call Params(Calling Number=,(Calling Name=)(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
   Called Number=49991(TON=Unknown, NPI=Unknown), Calling Translated=FALSE,
   Subscriber Type Str=, FinalDestinationFlag=FALSE, Outgoing Dial-peer=0, Call Count On=FALSE,
   Source Trkgrp Route Label=, Target Trkgrp Route Label=, tg_label_flag=0, Application Call Id=A000000005796251000000F5)
May  2 11:37:24.936: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
   
May  2 11:37:24.936: :cc_get_feature_vsa malloc success
May  2 11:37:24.936: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
   
May  2 11:37:24.936:  cc_get_feature_vsa count is 1
May  2 11:37:24.936: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
   
May  2 11:37:24.936: :FEATURE_VSA attributes are: feature_name:0,feature_time:140244942088524,feature_id:269
May  2 11:37:24.936: //-1/xxxxxxxxxxxx/VTSP:(0/2/0:1):-1:-1:-1/vtsp_allocate_cdb:  
   CDB=0x7F8D62297BF8
May  2 11:37:24.936: //-1/xxxxxxxxxxxx/VTSP:(0/2/0:1):-1:-1:-1/vtsp_insert_cdb: 
May  2 11:37:24.936: //553/8BE462318094/CCAPI/ccIFCallSetupRequestPrivate:
   SPI Call Setup Request Is Success; Interface Type=6, FlowMode=1
May  2 11:37:24.936: //553/8BE462318094/CCAPI/ccCallSetContext:
   Context=0x7F8D624A2FC0
May  2 11:37:24.936: //-1/xxxxxxxxxxxx/CCAPI/ccIFCallSetupRequestPrivate:
   Interface=0x7F8D50EB72A0, Interface Type=9, Destination=0.0.0.0, Mode=0x9,
   Call Params(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=, FinalDestinationFlag=FALSE, Outgoing Dial-peer=0, Call Count On=TRUE,
   Source Trkgrp Route Label=, Target Trkgrp Route Label=, tg_label_flag=0, Application Call Id=A000000005796251000000F5)
May  2 11:37:24.936: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
   
May  2 11:37:24.936: :cc_get_feature_vsa malloc success
May  2 11:37:24.936: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
   
May  2 11:37:24.937:  cc_get_feature_vsa count is 2
May  2 11:37:24.937: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
   
May  2 11:37:24.937: :FEATURE_VSA attributes are: feature_name:0,feature_time:140244942088300,feature_id:270
May  2 11:37:24.937: //554/8BE462318094/CCAPI/ccIFCallSetupRequestPrivate:
   SPI Call Setup Request Is Success; Interface Type=9, FlowMode=1
May  2 11:37:24.937: //554/8BE462318094/CCAPI/ccCallSetContext:
   Context=0x7F8D624A2EF8
May  2 11:37:24.937: //-1/xxxxxxxxxxxx/VTSP:(0/2/0:1):-1:-1:-1/vtsp_process_event:  
   [state:INVALID STATE MACHINE, event:E_CC_SETUP_REQ]
May  2 11:37:24.937: htsp_timer_stop3 
May  2 11:37:24.937: //553/8BE462318094/VTSP:(0/2/0:1):-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 11:37:24.937: //553/8BE462318094/VTSP:(0/2/0:1):-1:-1:-1/vtsp_do_call_setup_req: 
May  2 11:37:24.937: //554/8BE462318094/CCAPI/cc_api_call_connected:
   Interface=0x7F8D50EB72A0, Data Bitmask=0x0, Progress Indication=NULL(0),
   Connection Handle=0
May  2 11:37:24.937: //554/8BE462318094/CCAPI/cc_api_call_connected:
   Call Entry(Connected=TRUE, Responsed=TRUE, Retry Count=0)
May  2 11:37:24.937: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_opened_cb: 
May  2 11:37:24.937: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_process_event:  
   [state:S_SETUP_REQ_PEND, event:E_VTSP_DSM_OPEN_SUCCESS]
May  2 11:37:24.937: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/act_setup_req_pend_succ: 
May  2 11:37:24.937: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_request_call:  
   Mode=9, Peer=0
May  2 11:37:24.937: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_create_call_active_on_setup_req:  
   Target Carrier ID=
May  2 11:37:24.937: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_create_call_active_on_setup_req:  
   Source Carrier ID=htsp_setup_req
May  2 11:37:24.937:  Orig called num:49991
May  2 11:37:24.937: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_request_call:  
   Progress Indication=0, Info Trans Capability=0
   Calling Number=, TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed
   Called Number=49991, TON=Unknown, NPI=Unknown
May  2 11:37:24.937: htsp_process_event: [0/2/0:1(24), EM_ONHOOK, E_HTSP_SETUP_REQ]em_onhook_setup 
May  2 11:37:24.937: em_offhook (0)vnm_dsp_set_sig_state:[recEive and transMit0/2/0:1(24)] set signal state = 0x8
May  2 11:37:24.937: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_process_event:  
   [state:S_SETUP_REQUEST, event:E_TSP_PROCEEDING]
May  2 11:37:24.938: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/act_setup_pend_proceeding: 
May  2 11:37:24.938: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_timer:  
   Timer Start Time=562974148, Timer Value=25000(ms)
May  2 11:37:24.938: //553/8BE462318094/CCAPI/cc_api_call_proceeding:
   Interface=0x7F8D4B274548, Progress Indication=NULL(0)
May  2 11:37:24.938: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/act_setup_pend_proceeding:  
   Peer=0, Progress Indication=0, Return Code=2
May  2 11:37:24.938: //553/8BE462318094/CCAPI/ccCallModify:
   Nominator=0x1000, Params=0x7F8D619352D4, Call Id=553
May  2 11:37:24.938: //553/8BE462318094/CCAPI/ccCallReportDigits:
   (callID=0x229, digit_event=0x1, enable=TRUE, consume=FALSE)
May  2 11:37:24.938: //553/8BE462318094/CCAPI/ccCallReportDigits:
   Enabled=TRUE, Call Id=553
May  2 11:37:24.938: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_report_digit_control: 
May  2 11:37:24.938: //553/8BE462318094/CCAPI/cc_api_call_report_digits_done:
   (vdbPtr=0x7F8D4B274548, callID=0x229, disp=0, digit_event=0x1, enable=TRUE, consume=FALSE)
May  2 11:37:24.938: //553/8BE462318094/CCAPI/cc_api_call_report_digits_done:
   Enabled=TRUE, Disposition=0x0, Interface=0x7F8D4B274548, Call Id=553
May  2 11:37:24.938: //553/8BE462318094/CCAPI/cc_api_call_report_digits_done:
   Call Entry(Initial Digit Timeout=15000(ms), Inter Digit Timeout=10000(ms))
May  2 11:37:24.938: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_report_digit_control:  
   Digit Reporting=TRUE
May  2 11:37:24.938: //553/8BE462318094/CCAPI/ccConferenceCreate:
   (confID=0xFFFFFFFFFFFFFFFF, callID1=0x229, gcid=0-0-0-0, tag=0x0)
May  2 11:37:24.938: //554/8BE462318094/CCAPI/ccConferenceCreate:
   (confID=0xFFFFFFFFFFFFFFFF, callID2=0x22A, gcid=0-0-0-0, tag=0x0)
May  2 11:37:24.938: //553/8BE462318094/CCAPI/ccConferenceCreate:
   Conference Id=0xFFFFFFFFFFFFFFFF, Call Id1=553, Call Id2=554, Tag=0x0
May  2 11:37:24.938: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_bridge_check_cb: 
May  2 11:37:24.938: htsp_call_bridged invoked
May  2 11:37:24.938: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_bridge_check_cb:exit@1496 
May  2 11:37:24.938: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_bridge_status_cb: 
May  2 11:37:24.938: //553/8BE462318094/CCAPI/cc_api_bridge_done:
   Conference Id=0x86, Source Interface=0x7F8D4B274548, Source Call Id=553,
   Destination Call Id=554, Disposition=0x0, Tag=0xFFFFFFFFFFFFFFFF
May  2 11:37:24.938: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_save_fax_config: 
May  2 11:37:24.938: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_save_fax_config:  
   Fax Relay=DISABLED - MGCP Application
   Primary Fax Protocol=IGNORE_FAX_RELAY, Fallback Fax Protocol=IGNORE_FAX_RELAY
   Fax Relay CM Suppression :=ENABLED, Fax Relay ANS Suppression :=DISABLED
   Fax Parameters Set By=MGCP Call Type
May  2 11:37:24.938: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_set_fax_feat_param: 
May  2 11:37:24.938: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_save_tty_config: 
May  2 11:37:24.938: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_save_tty_config:  
   Save TTY configuration
May  2 11:37:24.938: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_set_tty_feat_param: 
May  2 11:37:24.938: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_set_tty_feat_param:  
   Set TTY feat parameters
May  2 11:37:24.938: //554/xxxxxxxxxxxx/CCAPI/cc_api_get_xcode_stream:
   
May  2 11:37:24.938: cc_api_get_xcode_stream : 4983
May  2 11:37:24.938: //554/xxxxxxxxxxxx/CCAPI/cc_api_ha_call_active_notify:
   
May  2 11:37:24.938: call_info mainst_callID:0x22A, peer_callID:0x229, confID:0x86, spi_type:6, media_flo_thru:1,num_streams:1, swmtpmsp_present:0

May  2 11:37:24.938: //554/xxxxxxxxxxxx/CCAPI/cc_api_ha_call_active_notify:
   
May  2 11:37:24.938:   stream[0]: callid:0x22A, media_passthrough:0
May  2 11:37:24.938: //554/8BE462318094/CCAPI/cc_api_bridge_done:
   Conference Id=0x86, Source Interface=0x7F8D50EB72A0, Source Call Id=554,
   Destination Call Id=553, Disposition=0x0, Tag=0x0
May  2 11:37:24.938: //553/8BE462318094/CCAPI/cc_generic_bridge_done:
   Conference Id=0x86, Source Interface=0x7F8D50EB72A0, Source Call Id=554,
   Destination Call Id=553, Disposition=0x0, Tag=0x0
May  2 11:37:24.938: //553/8BE462318094/CCAPI/ccConferenceCreate:
   Call Entry(Conference Id=0x86, Destination Call Id=554)
May  2 11:37:24.938: //554/8BE462318094/CCAPI/ccConferenceCreate:
   Call Entry(Conference Id=0x86, Destination Call Id=553)
May  2 11:37:24.938: //553/8BE462318094/CCAPI/ccConferenceCreate:
   
May  2 11:37:24.938: confID:0x86; callEntry1 callID1:0x229, type:6; callEntry2 callID2:0x22A, type:9

May  2 11:37:24.938: htsp_process_event: [0/2/0:1(24), EM_BRANCH, EM_EVENT_WINK]
May  2 11:37:24.938: em_start_timer: 550 ms 
May  2 11:37:24.938: htsp_timer - 550 msec
May  2 11:37:24.938: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_process_event:  
   [state:S_NULL, event:E_CC_DO_CAPS_IND]
May  2 11:37:24.938: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_peer_event_cb:  
   Event=E_DSM_CC_CAPS_IND
May  2 11:37:24.938: //553/8BE462318094/CCAPI/cc_api_caps_ind:
   Destination Interface=0x7F8D50EB72A0, Destination Call Id=554, Source Call Id=553,
   Caps(Codec=0x1, Fax Rate=0x1, Fax Version:=0, Vad=0x1,
   Modem=0x2, Codec Bytes=20, Signal Type=3)
May  2 11:37:24.938: //553/8BE462318094/CCAPI/cc_api_caps_ind:
   Caps(Playout Mode=1, Playout Initial=60(ms), Playout Min=40(ms),
   Playout Max=1000(ms), Fax Nom=300(ms))
May  2 11:37:24.938: //554/8BE462318094/CCAPI/cc_api_caps_ind:
   Destination Interface=0x7F8D4B274548, Destination Call Id=553, Source Call Id=554,
   Caps(Codec=0x1, Fax Rate=0x2, Fax Version:=0, Vad=0x1,
   Modem=0x2, Codec Bytes=160, Signal Type=2)
May  2 11:37:24.938: //554/8BE462318094/CCAPI/cc_api_caps_ind:
   Caps(Playout Mode=1, Playout Initial=60(ms), Playout Min=40(ms),
   Playout Max=1000(ms), Fax Nom=300(ms))
May  2 11:37:24.938: //554/8BE462318094/CCAPI/cc_api_caps_ack:
   Destination Interface=0x7F8D4B274548, Destination Call Id=553, Source Call Id=554,
   Caps(Codec=g711ulaw(0x1), Fax Rate=FAX_RATE_VOICE(0x2), Fax Version:=0, Vad=OFF(0x1),
   Modem=ON(0x2), Codec Bytes=160, Signal Type=2, Seq Num Start=9205)
May  2 11:37:24.938: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_process_event:  
   [state:S_NULL, event:E_CC_CAPS_IND]
May  2 11:37:24.938: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/act_setup_req_pend_defer:  
   Event=67
May  2 11:37:24.939: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_opened_cb: 
May  2 11:37:24.939: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_call_mod_done_cb: 
May  2 11:37:24.939: //553/8BE462318094/CCAPI/cc_api_call_modify_done:
   Result=0, Interface=0x7F8D4B274548, Call Id=553
May  2 11:37:24.939: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_save_fax_config: 
May  2 11:37:24.939: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_save_fax_config:  
   Fax Relay=DISABLED - MGCP Application
   Primary Fax Protocol=IGNORE_FAX_RELAY, Fallback Fax Protocol=IGNORE_FAX_RELAY
   Fax Relay CM Suppression :=ENABLED, Fax Relay ANS Suppression :=DISABLED
   Fax Parameters Set By=MGCP Call Type
May  2 11:37:24.939: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_set_fax_feat_param: 
May  2 11:37:24.939: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_process_event:  
   [state:S_NULL, event:E_VTSP_DSM_OPEN_SUCCESS]
May  2 11:37:24.939: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/act_setup_req_wait_pend_success:  
   Event=76
May  2 11:37:24.939: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_timer_stop:  
   Timer Stop Time=562974148
May  2 11:37:24.939: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_peer_event_cb:  
   Event=E_DSM_CC_CAPS_ACK
May  2 11:37:24.939: //553/8BE462318094/CCAPI/cc_api_caps_ack:
   Destination Interface=0x7F8D50EB72A0, Destination Call Id=554, Source Call Id=553,
   Caps(Codec=g711ulaw(0x1), Fax Rate=FAX_RATE_VOICE(0x2), Fax Version:=0, Vad=OFF(0x1),
   Modem=ON(0x2), Codec Bytes=160, Signal Type=2, Seq Num Start=9205)
May  2 11:37:24.939: htsp_process_event: [0/2/0:1(24), EM_WAIT_WINKUP, E_HTSP_VOICE_CUT_THROUGH]
May  2 11:37:24.939: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_feature_notify_cb:  
   Feature ID=0, Feature Status=1
May  2 11:37:24.939: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_reactivate_ringback: 
May  2 11:37:24.939: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_reactivate_ringback:exit@1287 
May  2 11:37:24.939: //553/8BE462318094/CCAPI/cc_api_voice_mode_event:
   Call Id=553
May  2 11:37:24.939: //553/8BE462318094/CCAPI/cc_api_voice_mode_event:
   Call Entry(Context=0x7F8D624A2FC0)
May  2 11:37:24.939: htsp_process_event: [0/2/0:1(24), EM_WAIT_WINKUP, E_HTSP_VOICE_CUT_THROUGH]
May  2 11:37:24.939: //553/8BE462318094/CCAPI/cc_process_notify_bridge_done:
   Conference Id=0x86, Call Id1=553, Call Id2=554
May  2 11:37:24.939: MGCP Packet sent to [IP]:2427--->
200 818955 OK
I: D

v=0

c=IN IP4 10.3.3.254

m=audio 8266 RTP/AVP 0 100

a=rtpmap:100 X-NSE/8000

a=fmtp:100 192-194

<---

May  2 11:37:24.939: //553/8BE462318094/MGCP|S0/SU2/DS1-0/24|-1|-1/<VOICE>/process_start_signal(4122):[lvl=2]process_start_signal(): FAIL with rc: 8, need to reject the whole list
May  2 11:37:24.940: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_fpi_event_cb:  
   Event=E_DSMP_FPI_ENABLE_TDM_RTCP
May  2 11:37:25.488: htsp_process_event: [0/2/0:1(24), EM_WAIT_WINKUP, E_HTSP_EVENT_TIMER]em_wink_timeout 
May  2 11:37:25.488: em_stop_timers 
May  2 11:37:25.488: htsp_timer_stop2 em_onhook (0)vnm_dsp_set_sig_state:[recEive and transMit0/2/0:1(24)] set signal state = 0x0
May  2 11:37:25.489: em_start_timer: 400 ms 
May  2 11:37:25.489: htsp_timer - 400 msec
May  2 11:37:25.489: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_process_event:  
   [state:S_SETUP_REQ_PROC, event:E_TSP_DISCONNECT_IND]
May  2 11:37:25.489: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/act_setup_pend_release_ind:  
   Cause Value=44
May  2 11:37:25.489: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_ring_noan_timer_stop:  
   Timer Stop Time=562974203
May  2 11:37:25.489: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_cc_call_disconnected: 
May  2 11:37:25.489: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_cc_call_disconnected:  
   Cause Value=44
May  2 11:37:25.489: //553/8BE462318094/CCAPI/cc_api_call_disconnected:
   Cause Value=44, Interface=0x7F8D4B274548, Call Id=553
May  2 11:37:25.489: //553/8BE462318094/CCAPI/cc_api_call_disconnected:
   Call Entry(Responsed=TRUE, Cause Value=44, Retry Count=0)
May  2 11:37:25.489: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_set_release_source:  
   Release Direction=PSTN, Release Source=Called Party-PSTN
May  2 11:37:25.489: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/act_setup_pend_release_ind:  
   Peer=0
May  2 11:37:25.489: //553/8BE462318094/CCAPI/ccCallDisconnect:
   Cause Value=16, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=44)
May  2 11:37:25.489: //553/8BE462318094/CCAPI/ccCallDisconnect:
   Cause Value=44, Call Entry(Responsed=TRUE, Cause Value=44)
May  2 11:37:25.489: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_call_disconnect:  
   [Out Of Service]-Tone Played In Direction [Both]
May  2 11:37:25.489: MGCP Packet sent to [IP]:2427--->
NTFY 520787753 S0/SU2/DS1-0/24@RV-4451-VA-CLEV.domain.com MGCP 0.1
N: ca@[IP]:2427
X: 17
O: DT/of(dt/sup)
<---

May  2 11:37:25.489: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_process_event:  
   [state:S_WAIT_HOST_DISC, event:E_CC_DISCONNECT]
May  2 11:37:25.489: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/act_host_disc_cleanup:  
   dsm_indicate_error=0, short_cleardown_timeout=1, Mode=9
May  2 11:37:25.489: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_save_fax_config: 
May  2 11:37:25.489: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_save_fax_config:  
   Fax Relay=DISABLED - MGCP Application
   Primary Fax Protocol=IGNORE_FAX_RELAY, Fallback Fax Protocol=IGNORE_FAX_RELAY
   Fax Relay CM Suppression :=ENABLED, Fax Relay ANS Suppression :=DISABLED
   Fax Parameters Set By=MGCP Call Type
May  2 11:37:25.489: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_set_fax_feat_param: 
May  2 11:37:25.489: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/act_host_disc_cleanup:  
   Exit State=16
May  2 11:37:25.492: MGCP Packet received from [IP]:2427--->
200 520787753 
<---

May  2 11:37:25.492: //-1/xxxxxxxxxxxx/MGCP/mgcp_mp_get_not_entity(830):[lvl=2]Invalid parameter (pkt 0x7F8D62287660 pkt->mgcp_parm_lines 0x0)
May  2 11:37:25.492: MGCP Packet received from [IP]:2427--->
DLCX 818957 S0/SU2/DS1-0/24@RV-4451-VA-CLEV.domain.com MGCP 0.1
C: A000000005796251000000F5
I: D
X: 17
<---

May  2 11:37:25.492: //554/8BE462318094/CCAPI/ccGetCallStatistics:
   Call Stats=0x7F8D623A72E0, Call Id=554
May  2 11:37:25.492: //553/8BE462318094/CCAPI/ccConferenceDestroy:
   Conference Id=0x86, Tag=0x0
May  2 11:37:25.492: //553/8BE462318094/CCAPI/ccConferenceDestroy:
   
May  2 11:37:25.492: confID:0x86; callEntry1 callID1:0x229, type:6; callEntry2 callID2:0x22A, type:9

May  2 11:37:25.492: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_fpi_event_cb:  
   Event=E_DSMP_FPI_DISABLE_TDM_RTCP
May  2 11:37:25.492: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_bridge_status_cb: 
May  2 11:37:25.492: //553/8BE462318094/CCAPI/cc_api_bridge_drop_done:
   Conference Id=0x86, Source Interface=0x7F8D4B274548, Source Call Id=553,
   Destination Call Id=554, Disposition=0x0, Tag=0x0
May  2 11:37:25.492: //554/xxxxxxxxxxxx/CCAPI/cc_api_get_xcode_stream:
   
May  2 11:37:25.492: cc_api_get_xcode_stream : 4983
May  2 11:37:25.492: //554/8BE462318094/CCAPI/cc_api_bridge_drop_done:
   Conference Id=0x86, Source Interface=0x7F8D50EB72A0, Source Call Id=554,
   Destination Call Id=553, Disposition=0x0, Tag=0x0
May  2 11:37:25.492: //553/8BE462318094/CCAPI/cc_generic_bridge_done:
   Conference Id=0x86, Source Interface=0x7F8D50EB72A0, Source Call Id=554,
   Destination Call Id=553, Disposition=0x0, Tag=0x0
May  2 11:37:25.492: //554/8BE462318094/CCAPI/ccCallDisconnect:
   Cause Value=16, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
May  2 11:37:25.492: //554/8BE462318094/CCAPI/ccCallDisconnect:
   Cause Value=16, Call Entry(Responsed=TRUE, Cause Value=16)
May  2 11:37:25.494: //554/8BE462318094/CCAPI/cc_api_nw_stats:
   Call Stats=0x7F8D57E003F8, Call Id=554
May  2 11:37:25.494: //554/8BE462318094/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x7F8D50EB72A0, Tag=0x0, Call Id=554,
   Call Entry(Disconnect Cause=16, Voice Class Cause Code=0, Retry Count=0)
May  2 11:37:25.494: //554/8BE462318094/CCAPI/cc_api_call_disconnect_done:
   Call Disconnect Event Sent
May  2 11:37:25.494: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
   
May  2 11:37:25.494: :cc_free_feature_vsa freeing 7F8D51F46860
May  2 11:37:25.494: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
   
May  2 11:37:25.494:  vsacount in free is 1
May  2 11:37:25.494: MGCP Packet sent to [IP]:2427--->
250 818957 OK
P: PS=0, OS=0, PR=0, OR=0, PL=0, JI=0, LA=0
<---

May  2 11:37:25.497: MGCP Packet received from [IP]:2427--->
RQNT 818958 S0/SU2/DS1-0/24@RV-4451-VA-CLEV.domain.com MGCP 0.1
X: 17
R: DT/sup, D/[0-9ABCD*#]
S: DT/rlc
Q: process,loop
<---

May  2 11:37:25.511: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_dsm_get_levels_done_cb: 
May  2 11:37:25.531: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_process_event:  
   [state:S_WAIT_STATS, event:E_VTSP_DSM_STATS_COMPLETE]
May  2 11:37:25.531: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/act_dsm_dsp_stats_complete: 
May  2 11:37:25.531: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_timer:  
   Timer Start Time=562974207, Timer Value=60000(ms)
May  2 11:37:25.531: htsp_process_event: [0/2/0:1(24), EM_GUARD_ALL, E_HTSP_RELEASE_REQ]
May  2 11:37:25.889: htsp_process_event: [0/2/0:1(24), EM_GUARD_ALL_RLS_REQ, E_HTSP_EVENT_TIMER]em_guard_all_timer 
May  2 11:37:25.889: em_stop_timers 
May  2 11:37:25.889: htsp_timer_stop 
May  2 11:37:25.889: em_stop_timers 
May  2 11:37:25.889: htsp_timer_stop2 
May  2 11:37:25.889: em_start_timer: 3000 ms 
May  2 11:37:25.889: htsp_timer - 3000 msec
May  2 11:37:25.903: htsp_dsp_message: RESP_SIG_STATUS: state=0x0 timestamp=0 systime=562974245
May  2 11:37:25.903: htsp_process_event: [0/2/0:1(24), EM_PARK, E_DSP_SIG_0000]em_park_onhook
May  2 11:37:25.903: htsp_timer_stop 
May  2 11:37:25.903: htsp_timer_stop2 htsp_report_onhook_sig
May  2 11:37:25.903: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_process_event:  
   [state:S_WAIT_RELEASE, event:E_TSP_CALL_FEATURE_IND]
May  2 11:37:25.903: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/act_call_feature_ind:  
   Feature Type=6
May  2 11:37:25.903: //553/8BE462318094/CCAPI/cc_api_call_feature:
   Feature Type=6, Interface=0x7F8D4B274548, Call Id=553
May  2 11:37:25.903: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_process_event:  
   [state:S_WAIT_RELEASE, event:E_TSP_DISCONNECT_CONF]
May  2 11:37:25.903: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/act_wrelease_release: 
May  2 11:37:25.903: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_play_busy_timer_stop:  
   Timer Stop Time=562974245
May  2 11:37:25.903: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_timer_stop:  
   Timer Stop Time=562974245
May  2 11:37:25.903: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_do_call_history: 
May  2 11:37:25.903: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_do_call_history:  
   Coder Rate=5
May  2 11:37:25.903: //553/8BE462318094/VTSP:(0/2/0:1):-1:1:1/vtsp_is_valid_dsm_handle:  
   DMGR=0x7F8D627A7760, VTSP CDB=0x7F8D62297BF8
May  2 11:37:25.903: //553/8BE462318094/MGCP|S0/SU2/DS1-0/24|-1|-1/<VOICE>/mgcp_cas_oc_conn_call_feature(3285):[lvl=2]unexpected call feature(6)
May  2 11:37:25.905: //553/8BE462318094/VTSP:(0/2/0:1):-1:-1:-1/vtsp_dsm_closed_cb: 
May  2 11:37:25.905: //553/8BE462318094/VTSP:(0/2/0:1):-1:-1:-1/vtsp_process_event:  
   [state:S_CLOSE_DSPRM, event:E_VTSP_DSM_CLOSE_COMPLETE]
May  2 11:37:25.905: //553/8BE462318094/VTSP:(0/2/0:1):-1:-1:-1/act_terminate: 
May  2 11:37:25.905: //553/8BE462318094/VTSP:(0/2/0:1):-1:-1:-1/vtsp_timer_stop:  
   Timer Stop Time=562974245
May  2 11:37:25.905: //553/8BE462318094/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x7F8D4B274548, Tag=0x0, Call Id=553,
   Call Entry(Disconnect Cause=44, Voice Class Cause Code=0, Retry Count=0)
May  2 11:37:25.905: //553/8BE462318094/CCAPI/cc_api_call_disconnect_done:
   Call Disconnect Event Sent
May  2 11:37:25.905: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
   
May  2 11:37:25.905: :cc_free_feature_vsa freeing 7F8D51F46940
May  2 11:37:25.905: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
   
May  2 11:37:25.905:  vsacount in free is 0
May  2 11:37:25.905: //-1/8BE462318094/VTSP:(0/2/0:1):-1:-1:-1/vtsp_free_cdb:  
   CDB=0x7F8D62297BF8
May  2 11:37:25.905: MGCP Packet sent to [IP]:2427--->
200 818958 OK
<---

May  2 11:37:25.905: MGCP Packet sent to [IP]:2427--->
NTFY 520787754 S0/SU2/DS1-0/24@RV-4451-VA-CLEV.domain.com MGCP 0.1
N: ca@[IP]:2427
X: 17
O: DT/rlc
<---

May  2 11:37:25.908: MGCP Packet received from [IP]:2427--->
200 520787754 
<---

May  2 11:37:25.908: //-1/xxxxxxxxxxxx/MGCP/mgcp_mp_get_not_entity(830):[lvl=2]Invalid parameter (pkt 0x7F8D622877C8 pkt->mgcp_parm_lines 0x0)
May  2 11:37:25.908: MGCP Packet received from [IP]:2427--->
RQNT 818959 S0/SU2/DS1-0/24@RV-4451-VA-CLEV.domain.com MGCP 0.1
X: 17
R: DT/sup, D/[0-9ABCD*#]
Q: process,loop
<---

May  2 11:37:25.908: MGCP Packet sent to [IP]:2427--->
200 818959 OK
<---

RV-4451-VA-CLEV#
RV-4451-VA-CLEV#u all
All possible debugging has been turned off
RV-4451-VA-CLEV#exit

R0g22 · ‎05-03-2018

There is a WINK timeout -

May 2 11:37:25.488: htsp_process_event: [0/2/0:1(24), EM_WAIT_WINKUP, E_HTSP_EVENT_TIMER]em_wink_timeout
May 2 11:37:25.488: em_stop_timers
May 2 11:37:25.488: htsp_timer_stop2 em_onhook (0)vnm_dsp_set_sig_state:[recEive and transMit0/2/0:1(24)] set signal state = 0x0
May 2 11:37:25.489: em_start_timer: 400 ms
May 2 11:37:25.489: htsp_timer - 400 msec

The IOS is expecting a wink-back but does not get a response so drops the call. Are you sure this needs to be wink-start and not immediate or maybe wink delay ? Is there a way to test incoming calls or maybe the cabling/patch panel etc ?

Joel Jackson · ‎05-03-2018

I can test the cable, sure. I'm positive it has to be wink-start though. It works if I move back to the old gateway which is also configured as a CAS T1 with wink-start. I tried the other methods (wink-immediate, etc) and those did not work.

R0g22 · ‎05-04-2018

Interesting. Can you try a different port on the same card ? Also, add an output for "show platform" and "show inventory". Let me know the IOS running as well.