TCL ev_feature event inconsistent

Version 1
    This document was generated from CDN thread

    Created by: James Clapper on 23-07-2012 11:09:24 AM
    Trying to capture digits after a hookflash event on a CAS T1. Tried to use the ev_hookflash but that would not even allow the script to load. Now trying to use the ev_feature event. It works in getting the hookflash and then triggering my digit collection, but only about 1 out of every 6 times. Not certain what is going on here? I have messed with the timing on the voice port, changed FSM, and now pretty much stuck.
     
    Here is the script. Below is the logs that show that there is a hookflash that occurs and that the event kicks off only sometimes.
     
    proc init { } {
    global dcparams
    global hooksxfrdest
    global status
    global dest
    set dcparams(enableReporting) true
    set dcparams(dialPlan) false
    infotag set evt_feature_report hookflash onhook offhook
    puts "\n Initializing script..................."
    }
    proc act_Setup { } {
    global dest
    # Ensure there is a DNIS or close
    if { [infotag get leg_isdid] } {
    set dest [infotag get leg_dnis]
    } else {
    call close
    }
    # Setup inbound leg
    leg setupack leg_incoming
    leg proceeding leg_incoming
    leg connect leg_incoming
    # Setup to the DNIS
     
    leg setup $dest callInfo leg_incoming
    }
    proc act_Connected { } {
     
    global status
    # Ensure DID connected
    set status [infotag get evt_status]
    if { $status == "ls_000"} {
    puts "\n Call to Number successful"
     
    } else {
    puts "\n Call to Number did not connect"
    call close
    }
    }
    proc act_DigitCollect { } {
    puts [infotag get evt_event]
    global dcparams
    puts "\n Collecting Digits..................."
    leg collectdigits leg_outgoing
    #leg collectdigits [infotag get leg_all] dcparams
    }
    proc act_Xfer { } {
    puts "\n Transfering..................."
    #Something here if I can get this to work all the time....
    }
    proc act_Cleanup { } {
    puts "\n Cleaning up..................."
    call close
    }
    init
    #------------------
    # State Machine
    #----------------------------------
    set fsm(any_state,ev_disconnected) "act_Cleanup same_state"
    ############## "Meat" of the script
    set fsm(CALL_INIT,ev_setup_indication) "act_Setup CONNECT"
    set fsm(CONNECT,ev_setup_done) "act_Connected CONNECTED"
    set fsm(CONNECTED,ev_feature) "act_DigitCollect XFEROUT"
    set fsm(XFEROUT,ev_collectdigits_done) "act_Xfer CLEANUP"
    set fsm(CLEANUP,ev_media_done) "act_Cleanup CALLEND"
    ############## Cleanup
    set fsm(CALLEND,ev_media_done) "act_Cleanup CALLDISCONNECT"
    set fsm(CALLDISCONNECT,ev_disconnected) "act_Cleanup same_state"
    set fsm(CALLDISCONNECT,ev_media_done) "act_Cleanup same_state"
    set fsm(CALLDISCONNECT,ev_disconnect_done) "act_Cleanup same_state"
    set fsm(CALLDISCONNECT,ev_leg_timer) "act_Cleanup same_state"
    fsm define fsm CALL_INIT
     
     

     
    q99921voipgw1#show log
    Syslog logging: enabled (266 messages dropped, 148 messages rate-limited, 0 flushes, 0 overruns, xml disabled, filtering disabled)
     
    No Active Message Discriminator.
     
     
     
    No Inactive Message Discriminator.
     
     
        Console logging: level debugging, 1044933 messages logged, xml disabled,
                         filtering disabled
        Monitor logging: level debugging, 37099 messages logged, xml disabled,
                         filtering disabled
        Buffer logging:  level debugging, 1045049 messages logged, xml disabled,
                        filtering disabled
        Exception Logging: size (8192 bytes)
        Count and timestamp logging messages: disabled
        Persistent logging: disabled
        Trap logging: level informational, 110786 message lines logged
            Logging to 10.44.33.63  (udp port 514, audit disabled,
                  link up),
                  110786 message lines logged,
                  0 message lines rate-limited,
                  0 message lines dropped-by-MD,
                  xml disabled, sequence number disabled
                  filtering disabled
            Logging to 10.44.28.5  (udp port 514, audit disabled,
                  link up),
                  110786 message lines logged,
                  0 message lines rate-limited,
                  0 message lines dropped-by-MD,
                  xml disabled, sequence number disabled
                  filtering disabled
            Logging to 10.170.100.23  (udp port 514, audit disabled,
                  link up),
                  110786 message lines logged,
                  0 message lines rate-limited,
                  0 message lines dropped-by-MD,
                  xml disabled, sequence number disabled
                  filtering disabled
     
    Log Buffer (1024000 bytes):
     
    Jul 10 01:48:32.673: //-1//HIFS:/hifs_ifs_cb: hifs ifs file read succeeded. size=4149, url=flash:CAST1hookflash_1.tcl
    Jul 10 01:48:32.673: //-1//HIFS:/hifs_free_idata: hifs_free_idata: 0x285E980C
    Jul 10 01:48:32.673: //-1//HIFS:/hifs_hold_idata: hifs_hold_idata: 0x285E980C
    Jul 10 01:48:32.673: //-1//AFW_:EE1D7D54C0000:/Tcl_Link: Linking script cast1hookflash
    Jul 10 01:48:32.675: //-1//TCL :EE1D7D54C0000:/tcl_InfotagObjCmd:  infotag set evt_feature_report hookflash onhook offhook
    Jul 10 01:48:32.675: //-1//TCL :EE1D7D54C0000:/tcl_InfotagSetObjCmd: infotag set evt_feature_report hookflash onhook offhook
    Jul 10 01:48:32.675: //-1//AFW_:EE1D7D54C0000:/vtw_ev_feature_report:
    Jul 10 01:48:32.675: //-1//AFW_:EE1D7D54C0000:/vtw_ev_feature_report: reportFeatureBitmap=0x1C
    Jul 10 01:48:32.675: //-1//TCL :EE1D7D54C0000:/tcl_PutsObjCmd:
    Initializing script...................
    Jul 10 01:48:32.675:
    Jul 10 01:48:32.675: //-1//TCL :EE1D7D54C0000:/tcl_FSMObjCmd:  fsm define fsm CALL_INIT
    Jul 10 01:48:32.675: //-1//TCL :EE1D7D54C0000:/tcl_FSMDefineObjCmd: State Machine: Array fsm: Start State: CALL_INIT
    Jul 10 01:48:32.675: //-1//TCL :EE1D7D54C0000:/tcl_FSMDefineObjCmd: FSM Data structure
    Jul 10 01:48:32.675: (CALLDISCONNECT(2), ev_leg_timer(1)--(act_Cleanup)-->(any_state(0))
    Jul 10 01:48:32.675: (CALLDISCONNECT(2), ev_media_done(175)--(act_Cleanup)-->(any_state(0))
    Jul 10 01:48:32.675: (CONNECTED(3), ev_feature(38)--(act_DigitCollect)-->(XFEROUT(4))
    Jul 10 01:48:32.675: (any_state(0), ev_disconnected(20)--(act_Cleanup)-->(any_state(0))
    Jul 10 01:48:32.675: (CALLEND(5), ev_media_done(175)--(act_Cleanup)-->(CALLDISCONNECT(2))
    Jul 10 01:48:32.675: (XFEROUT(4), ev_collectdigits_done(225)--(act_Xfer)-->(CLEANUP(6))
    Jul 10 01:48:32.675: (CONNECT(7), ev_setup_done(216)--(act_Connected)-->(CONNECTED(3))
    Jul 10 01:48:32.675: (CALLDISCONNECT(2), ev_disconnect_done(21)--(act_Cleanup)-->(any_state(0))
    Jul 10 01:48:32.675: (CALLDISCONNECT(2), ev_disconnected(20)--(act_Cleanup)-->(any_state(0))
    Jul 10 01:48:32.675: (CLEANUP(6), ev_media_done(175)--(act_Cleanup)-->(CALLEND(5))
    Jul 10 01:48:32.675: (CALL_INIT(1), ev_setup_indication(34)--(act_Setup)-->(CONNECT(7))
    Jul 10 01:48:32.675: FSM start state CALL_INIT(1)
    Jul 10 01:48:32.675: //-1//AFW_:EE1D7D54C0000:/Tcl_Link: Script cast1hookflash succesfully linked.
    Jul 10 01:48:42.162: //-1//AFW_:EE1D7D53D8000:/Tcl_Link: Linking script cast1hookflash
    Jul 10 01:48:42.162: //-1//TCL :EE1D7D53D8000:/tcl_InfotagObjCmd:  infotag set evt_feature_report hookflash onhook offhook
    Jul 10 01:48:42.162: //-1//TCL :EE1D7D53D8000:/tcl_InfotagSetObjCmd: infotag set evt_feature_report hookflash onhook offhook
    Jul 10 01:48:42.162: //-1//AFW_:EE1D7D53D8000:/vtw_ev_feature_report:
    Jul 10 01:48:42.162: //-1//AFW_:EE1D7D53D8000:/vtw_ev_feature_report: reportFeatureBitmap=0x1C
    Jul 10 01:48:42.162: //-1//TCL :EE1D7D53D8000:/tcl_PutsObjCmd:
    Initializing script...................
    Jul 10 01:48:42.162:
    Jul 10 01:48:42.162: //-1//TCL :EE1D7D53D8000:/tcl_FSMObjCmd:  fsm define fsm CALL_INIT
    Jul 10 01:48:42.162: //-1//TCL :EE1D7D53D8000:/tcl_FSMDefineObjCmd: State Machine: Array fsm: Start State: CALL_INIT
    Jul 10 01:48:42.162: //-1//TCL :EE1D7D53D8000:/tcl_FSMDefineObjCmd: FSM Data structure
    Jul 10 01:48:42.162: (CALLDISCONNECT(2), ev_leg_timer(1)--(act_Cleanup)-->(any_state(0))
    Jul 10 01:48:42.162: (CALLDISCONNECT(2), ev_media_done(175)--(act_Cleanup)-->(any_state(0))
    Jul 10 01:48:42.162: (CONNECTED(3), ev_feature(38)--(act_DigitCollect)-->(XFEROUT(4))
    Jul 10 01:48:42.162: (any_state(0), ev_disconnected(20)--(act_Cleanup)-->(any_state(0))
    Jul 10 01:48:42.162: (CALLEND(5), ev_media_done(175)--(act_Cleanup)-->(CALLDISCONNECT(2))
    Jul 10 01:48:42.162: (XFEROUT(4), ev_collectdigits_done(225)--(act_Xfer)-->(CLEANUP(6))
    Jul 10 01:48:42.162: (CONNECT(7), ev_setup_done(216)--(act_Connected)-->(CONNECTED(3))
    Jul 10 01:48:42.162: (CALLDISCONNECT(2), ev_disconnect_done(21)--(act_Cleanup)-->(any_state(0))
    Jul 10 01:48:42.162: (CALLDISCONNECT(2), ev_disconnected(20)--(act_Cleanup)-->(any_state(0))
    Jul 10 01:48:42.162: (CLEANUP(6), ev_media_done(175)--(act_Cleanup)-->(CALLEND(5))
    Jul 10 01:48:42.162: (CALL_INIT(1), ev_setup_indication(34)--(act_Setup)-->(CONNECT(7))
    Jul 10 01:48:42.162: FSM start state CALL_INIT(1)
    Jul 10 01:48:42.162: //-1//AFW_:EE1D7D53D8000:/Tcl_Link: Script cast1hookflash succesfully linked.
    Jul 10 01:48:42.162: //239520//TCL :/tcl_InfotagObjCmd:  infotag get leg_isdid
    Jul 10 01:48:42.162: //239520//TCL :/tcl_InfotagGetObjCmd: infotag get leg_isdid
    Jul 10 01:48:42.162: //239520//AFW_:/vtr_lg_incdid: argc 2 argindex 2
    Jul 10 01:48:42.162: //239520//TCL :/tcl_InfotagObjCmd:  infotag get leg_dnis
    Jul 10 01:48:42.162: //239520//TCL :/tcl_InfotagGetObjCmd: infotag get leg_dnis
    Jul 10 01:48:42.162: //239520//AFW_:/vtr_lg_dnis: argc 2 argindex 2
    Jul 10 01:48:42.162: //239520//TCL :/tcl_LegObjCmd:  leg setupack leg_incoming
    Jul 10 01:48:42.162: //239520//TCL :/tcl_LegSetupAckObjCmd: setupack leg_incoming
    Jul 10 01:48:42.162: //239520//AFW_:/vtd_lg_incoming: argc 2
    Jul 10 01:48:42.162: //239520//AFW_:/vtd_lg_incoming: Legs [239520 ]
    Jul 10 01:48:42.162: //239520//Tcl :/tcl_parseCallID_vartagObj: VARTAG Translation Leg Count=1
    Jul 10 01:48:42.162: //239520//TCL :/tcl_LegObjCmd:  leg proceeding leg_incoming
    Jul 10 01:48:42.162: //239520//TCL :/tcl_LegProceedObjCmd: proceeding leg_incoming
    Jul 10 01:48:42.162: //239520//AFW_:/vtd_lg_incoming: argc 2
    Jul 10 01:48:42.162: //239520//AFW_:/vtd_lg_incoming: Legs [239520 ]
    Jul 10 01:48:42.162: //239520//Tcl :/tcl_parseCallID_vartagObj: VARTAG Translation Leg Count=1
    Jul 10 01:48:42.162: //239520//TCL :/tcl_LegObjCmd:  leg connect leg_incoming
    Jul 10 01:48:42.162: //239520//TCL :/tcl_LegConnectObjCmd: connect leg_incoming
    Jul 10 01:48:42.162: //239520//AFW_:/vtd_lg_incoming: argc 2
    Jul 10 01:48:42.162: //239520//AFW_:/vtd_lg_incoming: Legs [239520 ]
    Jul 10 01:48:42.162: //239520//Tcl :/tcl_parseCallID_vartagObj: VARTAG Translation Leg Count=1
    Jul 10 01:48:42.162: //239520//TCL :/tcl_LegObjCmd:  leg setup sip:19528284207@10.170.47.11:5060 callInfo leg_incoming
    Jul 10 01:48:42.162: //239520//AFW_:/vtd_lg_incoming: argc 4
    Jul 10 01:48:42.162: //239520//AFW_:/vtd_lg_incoming: Legs [239520 ]
    Jul 10 01:48:42.162: //239520//Tcl :/tcl_parseCallID_vartagObj: VARTAG Translation Leg Count=1
    Jul 10 01:48:42.162: htsp_timer_stop3 htsp_setup_req
    Jul 10 01:48:42.164: htsp_process_event: [1/0:0(4), FXSLS_ONHOOK, E_HTSP_SETUP_REQ]fxsls_onhook_setuphtsp_alertvnm_dsp_set_sig_state:[Foreign Exchange Station 1/0:0(4)] set signal state = 0x0
    Jul 10 01:48:42.164: htsp_call_bridged invoked
    Jul 10 01:48:42.164: htsp_process_event: [1/0:0(4), FXSLS_WAIT_OFFHOOK, E_HTSP_VOICE_CUT_THROUGH]fxsls_waitoff_voice
    Jul 10 01:48:44.213: htsp_process_event: [1/0:0(4), FXSLS_WAIT_OFFHOOK, E_DSP_SIG_1100]fxsls_waitoff_offhookvnm_dsp_set_sig_state:[Foreign Exchange Station 1/0:0(4)] set signal state = 0x4vnm_dsp_set_sig_state:[Foreign Exchange Station 1/0:0(4)] set signal state = 0x6
    Jul 10 01:48:44.213: htsp_timer2 - 200 msec
    Jul 10 01:48:44.413: htsp_process_event: [1/0:0(4), FXSLS_WAIT_OFFHOOK, E_HTSP_EVENT_TIMER2]fxsls_offhook_dial htsp_dial
    Jul 10 01:48:44.413: htsp_process_event: [1/0:0(4), FXSLS_CONNECT, E_DSP_DIALING_DONE]fxsls_conn_dial_done
    Jul 10 01:48:44.413: //239520//TCL :/tcl_InfotagObjCmd:  infotag get evt_status
    Jul 10 01:48:44.413: //239520//TCL :/tcl_InfotagGetObjCmd: infotag get evt_status
    Jul 10 01:48:44.413: //239520//AFW_:/vtr_ev_status: argc 2 argindex 2
    Jul 10 01:48:44.413: //239520//TCL :/tcl_PutsObjCmd:
    Call to Number successful
    Jul 10 01:48:44.413:
    Jul 10 01:48:44.413: //239520//TCL :/tcl_InfotagObjCmd:  infotag get leg_all
    Jul 10 01:48:44.413: //239520//TCL :/tcl_InfotagGetObjCmd: infotag get leg_all
    Jul 10 01:48:44.413: //239520//AFW_:/vtr_lg_all: argc 2
    Jul 10 01:48:44.413: //239520//TCL :/tcl_LegObjCmd:  leg collectdigits 239520 239521 dcparams
    Jul 10 01:48:44.413: //239520//Digi:/tcl_LegDigitCollectObjCmd: collectdigits 239520 239521 dcparams
    Jul 10 01:48:44.413: //239520//Tcl :/tcl_parseCallID_vartagObj: VARTAG Translation Leg Count=2
    Jul 10 01:48:44.413: //239520//Digi:/C_DigitCollect_Start: Leg=239520, Dialplan=False, Diaplanterm=False, DigitReport=True, DigitConsume=False IgnoreInitialKey=False, IgnoreDTMFacceptINFO=False, Abortkey=^@, Terminationkey=^@, Numpatterns=0, Maxdigits=0, Mindigits=0, Interruptprompt=False, InterTimeout=-1000, Initialtimeout=-1000, Mask=0 Hotword=0
    Jul 10 01:48:44.413: //-1//Digi:/AFW_DigitCollect_New:
    Jul 10 01:48:44.413: //-1//Digi:HNCD4EAB66:/AFW_DigitCollect_New: DialPlan=FALSE AbortKey=^@ TermKey=^@ NumPatts=0
                  Enable=TRUE Consume=FALSE InterruptPrompt=FALSE minDigits=0 maxDigits=0 DialPlanTerm=FALSE hotword=0
    Jul 10 01:48:44.413: //239520/5EBE28000006/Digi:/DigitCollectStart_UpdateStats:
    Jul 10 01:48:44.413: //239520//Digi:/DigitCollect_MLPPTuning:
    Jul 10 01:48:44.413: //239520//Digi:/DigitCollect_MLPPTuning: Precednece Digit Collect not enabled
    Jul 10 01:48:44.413: //239520//Digi:/C_DigitCollect_Start: Leg=239521, Dialplan=False, Diaplanterm=False, DigitReport=True, DigitConsume=False IgnoreInitialKey=False, IgnoreDTMFacceptINFO=False, Abortkey=^@, Terminationkey=^@, Numpatterns=0, Maxdigits=0, Mindigits=0, Interruptprompt=False, InterTimeout=-1000, Initialtimeout=-1000, Mask=0 Hotword=0
    Jul 10 01:48:44.413: //-1//Digi:/AFW_DigitCollect_New:
    Jul 10 01:48:44.413: //-1//Digi:HNCD4EAB66:/AFW_DigitCollect_New: DialPlan=FALSE AbortKey=^@ TermKey=^@ NumPatts=0
                  Enable=TRUE Consume=FALSE InterruptPrompt=FALSE minDigits=0 maxDigits=0 DialPlanTerm=FALSE hotword=0
    Jul 10 01:48:44.413: //239521/5EBE28000006/Digi:/DigitCollectStart_UpdateStats:
    Jul 10 01:48:44.413: //239520//Digi:/DigitCollect_MLPPTuning:
    Jul 10 01:48:44.413: //239520//Digi:/DigitCollect_MLPPTuning: Precednece Digit Collect not enabled
    Jul 10 01:48:44.413: //239520//Digi:/AFW_M_DigitCollect_Action:
    Jul 10 01:48:44.413: //239520//Digi:/act_DCRunning_RDone: id=239520 Enable succeeded.enable=1 matchDialplan=0 numPatterns=0matchDialplanTerm=0
    Jul 10 01:48:44.413: //-1//Digi:/DigitCollect_Complete: DC_ENABLED. Digits=
    Jul 10 01:48:44.413: //239520//Digi:/AFW_M_DigitCollect_EventPreProcess:
    Jul 10 01:48:44.413: //239520//Digi:/DigitCollectEnd_UpdateStats:
    Jul 10 01:48:44.413: //239520//Digi:/AFW_M_DigitCollect_Action:
    Jul 10 01:48:44.413: //239520//Digi:/act_DCRunning_RDone: id=239521 Enable succeeded.enable=1 matchDialplan=0 numPatterns=0matchDialplanTerm=0
    Jul 10 01:48:44.413: //-1//Digi:/DigitCollect_Complete: DC_ENABLED. Digits=
    Jul 10 01:48:44.413: //239520//Digi:/AFW_M_DigitCollect_EventPreProcess:
    Jul 10 01:48:44.413: //239520//Digi:/DigitCollectEnd_UpdateStats:
    Jul 10 01:49:12.397: htsp_process_event: [1/0:0(4), FXSLS_CONNECT, E_DSP_SIG_0100]fxsls_offhook_onhook, HF duration Max=1000, HF duration Min=150
    Jul 10 01:49:12.397: htsp_timer - 1000 msec
    Jul 10 01:49:12.997: htsp_process_event: [1/0:0(4), FXSLS_CONNECT, E_DSP_SIG_1100]fxsls_offhook_offhookhtsp_hook_flash_ind
    Jul 10 01:49:12.997: htsp_timer_stop
    Jul 10 01:49:12.997: //239520//TCL :/tcl_InfotagObjCmd:  infotag get evt_event
    Jul 10 01:49:12.997: //239520//TCL :/tcl_InfotagGetObjCmd: infotag get evt_event
    Jul 10 01:49:12.997: //239520//AFW_:/vtr_ev_event: argc 2
    Jul 10 01:49:12.997: //239520//AFW_:/vtr_ev_event: Event [ev_feature]
    Jul 10 01:49:12.997: //239520//TCL :/tcl_PutsObjCmd: ev_feature
    Jul 10 01:49:12.997:
    Jul 10 01:49:12.997: //239520//TCL :/tcl_PutsObjCmd:
    Collecting Digits...................
    Jul 10 01:49:12.997:
    Jul 10 01:49:12.997: //239520//TCL :/tcl_LegObjCmd:  leg collectdigits leg_outgoing
    Jul 10 01:49:12.997: //239520//Digi:/tcl_LegDigitCollectObjCmd: collectdigits leg_outgoing
    Jul 10 01:49:12.997: //239520//AFW_:/vtd_lg_outgoing: argc 2
    Jul 10 01:49:12.997: //239520//AFW_:/vtd_lg_outgoing: Legs [239521 ]
    Jul 10 01:49:12.997: //239520//Tcl :/tcl_parseCallID_vartagObj: VARTAG Translation Leg Count=1
    Jul 10 01:49:12.997: //239520//Digi:/C_DigitCollect_Start: Leg=239521, Dialplan=True, Diaplanterm=True, DigitReport=False, DigitConsume=False IgnoreInitialKey=False, IgnoreDTMFacceptINFO=False, Abortkey=^@, Terminationkey=^@, Numpatterns=0, Maxdigits=0, Mindigits=0, Interruptprompt=False, InterTimeout=-1000, Initialtimeout=-1000, Mask=0 Hotword=0
    Jul 10 01:49:12.997: //-1//Digi:/AFW_DigitCollect_New:
    Jul 10 01:49:12.997: //-1//Digi:HNCD4F1B06:/AFW_DigitCollect_New: DialPlan=TRUE AbortKey=^@ TermKey=^@ NumPatts=0
                  Enable=FALSE Consume=FALSE InterruptPrompt=FALSE minDigits=0 maxDigits=0 DialPlanTerm=TRUE hotword=0
    Jul 10 01:49:12.997: //239521/5EBE28000006/Digi:/DigitCollectStart_UpdateStats:
    Jul 10 01:49:12.997: //239520//Digi:/DigitCollect_MLPPTuning:
    Jul 10 01:49:12.997: //239520//Digi:/DigitCollect_MLPPTuning: Precednece Digit Collect not enabled
    Jul 10 01:49:12.997: //239520//Digi:/AFW_M_DigitCollect_Action:
    Jul 10 01:49:12.997: //239520//Digi:/act_DCRunning_RDone: id=239521 Enable succeeded.enable=0 matchDialplan=1 numPatterns=0matchDialplanTerm=1
    Jul 10 01:49:14.386: htsp_digit_ready(1/0:0(4)): digit = 1
    Jul 10 01:49:14.386: //239520//Digi:/AFW_M_DigitCollect_Action:
    Jul 10 01:49:14.386: //239520//Digi:/act_DCRunning_Digit: : pLeg 239521 Digit 1 Tone Mode 0
    Jul 10 01:49:14.386: //239520//Digi:/DigitCollect_TreatDigit:
    Jul 10 01:49:14.386: //239520//Digi:/DigitCollect_DialPlanMatch: pattern offset=0, digits=1
    Jul 10 01:49:14.386: //239520//Digi:/DigitCollect_DialPlanMatch: src carrier id:, tgt carrier id:
    Jul 10 01:49:14.386: //239520//Digi:/DigitCollect_DialPlanMatch: Match single infotype
    Jul 10 01:49:14.546: htsp_digit_ready(1/0:0(4)): digit = 3
    Jul 10 01:49:14.546: //239520//Digi:/AFW_M_DigitCollect_Action:
    Jul 10 01:49:14.546: //239520//Digi:/act_DCRunning_Digit: : pLeg 239521 Digit 3 Tone Mode 0
    Jul 10 01:49:14.546: //239520//Digi:/DigitCollect_TreatDigit:
    Jul 10 01:49:14.546: //239520//Digi:/DigitCollect_DialPlanMatch: pattern offset=0, digits=13
    Jul 10 01:49:14.546: //239520//Digi:/DigitCollect_DialPlanMatch: src carrier id:, tgt carrier id:
    Jul 10 01:49:14.546: //239520//Digi:/DigitCollect_DialPlanMatch: Match single infotype
    Jul 10 01:49:14.706: htsp_digit_ready(1/0:0(4)): digit = 9
    Jul 10 01:49:14.706: //239520//Digi:/AFW_M_DigitCollect_Action:
    Jul 10 01:49:14.706: //239520//Digi:/act_DCRunning_Digit: : pLeg 239521 Digit 9 Tone Mode 0
    Jul 10 01:49:14.706: //239520//Digi:/DigitCollect_TreatDigit:
    Jul 10 01:49:14.706: //239520//Digi:/DigitCollect_DialPlanMatch: pattern offset=0, digits=139
    Jul 10 01:49:14.706: //239520//Digi:/DigitCollect_DialPlanMatch: src carrier id:, tgt carrier id:
    Jul 10 01:49:14.706: //239520//Digi:/DigitCollect_DialPlanMatch: Match single infotype
    Jul 10 01:49:14.838: htsp_digit_ready(1/0:0(4)): digit = 9
    Jul 10 01:49:14.838: //239520//Digi:/AFW_M_DigitCollect_Action:
    Jul 10 01:49:14.838: //239520//Digi:/act_DCRunning_Digit: : pLeg 239521 Digit 9 Tone Mode 0
    Jul 10 01:49:14.838: //239520//Digi:/DigitCollect_TreatDigit:
    Jul 10 01:49:14.838: //239520//Digi:/DigitCollect_DialPlanMatch: pattern offset=0, digits=1399
    Jul 10 01:49:14.838: //239520//Digi:/DigitCollect_DialPlanMatch: src carrier id:, tgt carrier id:
    Jul 10 01:49:14.838: //239520//Digi:/DigitCollect_DialPlanMatch: Match single infotype
    Jul 10 01:49:14.998: htsp_digit_ready(1/0:0(4)): digit = 9
    Jul 10 01:49:14.998: //239520//Digi:/AFW_M_DigitCollect_Action:
    Jul 10 01:49:14.998: //239520//Digi:/act_DCRunning_Digit: : pLeg 239521 Digit 9 Tone Mode 0
    Jul 10 01:49:14.998: //239520//Digi:/DigitCollect_TreatDigit:
    Jul 10 01:49:14.998: //239520//Digi:/DigitCollect_DialPlanMatch: pattern offset=0, digits=13999
    Jul 10 01:49:14.998: //239520//Digi:/DigitCollect_DialPlanMatch: src carrier id:, tgt carrier id:
    Jul 10 01:49:14.998: //239520//Digi:/DigitCollect_DialPlanMatch: Match single infotype
    Jul 10 01:49:15.158: htsp_digit_ready(1/0:0(4)): digit = 5
    Jul 10 01:49:15.158: //239520//Digi:/AFW_M_DigitCollect_Action:
    Jul 10 01:49:15.158: //239520//Digi:/act_DCRunning_Digit: : pLeg 239521 Digit 5 Tone Mode 0
    Jul 10 01:49:15.158: //239520//Digi:/DigitCollect_TreatDigit:
    Jul 10 01:49:15.158: //239520//Digi:/DigitCollect_DialPlanMatch: pattern offset=0, digits=139995
    Jul 10 01:49:15.158: //239520//Digi:/DigitCollect_DialPlanMatch: src carrier id:, tgt carrier id:
    Jul 10 01:49:15.158: //239520//Digi:/DigitCollect_DialPlanMatch: Match single infotype
    Jul 10 01:49:15.318: htsp_digit_ready(1/0:0(4)): digit = 2
    Jul 10 01:49:15.318: //239520//Digi:/AFW_M_DigitCollect_Action:
    Jul 10 01:49:15.318: //239520//Digi:/act_DCRunning_Digit: : pLeg 239521 Digit 2 Tone Mode 0
    Jul 10 01:49:15.318: //239520//Digi:/DigitCollect_TreatDigit:
    Jul 10 01:49:15.318: //239520//Digi:/DigitCollect_DialPlanMatch: pattern offset=0, digits=1399952
    Jul 10 01:49:15.318: //239520//Digi:/DigitCollect_DialPlanMatch: src carrier id:, tgt carrier id:
    Jul 10 01:49:15.318: //239520//Digi:/DigitCollect_DialPlanMatch: Match single infotype
    Jul 10 01:49:15.478: htsp_digit_ready(1/0:0(4)): digit = 2
    Jul 10 01:49:15.478: //239520//Digi:/AFW_M_DigitCollect_Action:
    Jul 10 01:49:15.478: //239520//Digi:/act_DCRunning_Digit: : pLeg 239521 Digit 2 Tone Mode 0
    Jul 10 01:49:15.478: //239520//Digi:/DigitCollect_TreatDigit:
    Jul 10 01:49:15.478: //239520//Digi:/DigitCollect_DialPlanMatch: pattern offset=0, digits=13999522
    Jul 10 01:49:15.478: //239520//Digi:/DigitCollect_DialPlanMatch: src carrier id:, tgt carrier id:
    Jul 10 01:49:15.478: //239520//Digi:/DigitCollect_DialPlanMatch: Match single infotype
    Jul 10 01:49:15.638: htsp_digit_ready(1/0:0(4)): digit = 3
    Jul 10 01:49:15.638: //239520//Digi:/AFW_M_DigitCollect_Action:
    Jul 10 01:49:15.638: //239520//Digi:/act_DCRunning_Digit: : pLeg 239521 Digit 3 Tone Mode 0
    Jul 10 01:49:15.638: //239520//Digi:/DigitCollect_TreatDigit:
    Jul 10 01:49:15.638: //239520//Digi:/DigitCollect_DialPlanMatch: pattern offset=0, digits=139995223
    Jul 10 01:49:15.638: //239520//Digi:/DigitCollect_DialPlanMatch: src carrier id:, tgt carrier id:
    Jul 10 01:49:15.638: //239520//Digi:/DigitCollect_DialPlanMatch: Match single infotype
    Jul 10 01:49:15.798: htsp_digit_ready(1/0:0(4)): digit = 8
    Jul 10 01:49:15.798: //239520//Digi:/AFW_M_DigitCollect_Action:
    Jul 10 01:49:15.798: //239520//Digi:/act_DCRunning_Digit: : pLeg 239521 Digit 8 Tone Mode 0
    Jul 10 01:49:15.798: //239520//Digi:/DigitCollect_TreatDigit:
    Jul 10 01:49:15.798: //239520//Digi:/DigitCollect_DialPlanMatch: pattern offset=0, digits=1399952238
    Jul 10 01:49:15.798: //239520//Digi:/DigitCollect_DialPlanMatch: src carrier id:, tgt carrier id:
    Jul 10 01:49:15.798: //239520//Digi:/DigitCollect_DialPlanMatch: Match single infotype
    Jul 10 01:49:15.958: htsp_digit_ready(1/0:0(4)): digit = 3
    Jul 10 01:49:15.958: //239520//Digi:/AFW_M_DigitCollect_Action:
    Jul 10 01:49:15.958: //239520//Digi:/act_DCRunning_Digit: : pLeg 239521 Digit 3 Tone Mode 0
    Jul 10 01:49:15.958: //239520//Digi:/DigitCollect_TreatDigit:
    Jul 10 01:49:15.958: //239520//Digi:/DigitCollect_DialPlanMatch: pattern offset=0, digits=13999522383
    Jul 10 01:49:15.958: //239520//Digi:/DigitCollect_DialPlanMatch: src carrier id:, tgt carrier id:
    Jul 10 01:49:15.958: //239520//Digi:/DigitCollect_DialPlanMatch: Match single infotype
    Jul 10 01:49:16.118: htsp_digit_ready(1/0:0(4)): digit = 4
    Jul 10 01:49:16.118: //239520//Digi:/AFW_M_DigitCollect_Action:
    Jul 10 01:49:16.118: //239520//Digi:/act_DCRunning_Digit: : pLeg 239521 Digit 4 Tone Mode 0
    Jul 10 01:49:16.118: //239520//Digi:/DigitCollect_TreatDigit:
    Jul 10 01:49:16.118: //239520//Digi:/DigitCollect_DialPlanMatch: pattern offset=0, digits=139995223834
    Jul 10 01:49:16.118: //239520//Digi:/DigitCollect_DialPlanMatch: src carrier id:, tgt carrier id:
    Jul 10 01:49:16.118: //239520//Digi:/DigitCollect_DialPlanMatch: Match single infotype
    Jul 10 01:49:16.278: htsp_digit_ready(1/0:0(4)): digit = 5
    Jul 10 01:49:16.278: //239520//Digi:/AFW_M_DigitCollect_Action:
    Jul 10 01:49:16.278: //239520//Digi:/act_DCRunning_Digit: : pLeg 239521 Digit 5 Tone Mode 0
    Jul 10 01:49:16.278: //239520//Digi:/DigitCollect_TreatDigit:
    Jul 10 01:49:16.278: //239520//Digi:/DigitCollect_DialPlanMatch: pattern offset=0, digits=1399952238345
    Jul 10 01:49:16.278: //239520//Digi:/DigitCollect_DialPlanMatch: src carrier id:, tgt carrier id:
    Jul 10 01:49:16.278: //239520//Digi:/DigitCollect_DialPlanMatch: Match single infotype
    Jul 10 01:49:16.438: htsp_digit_ready(1/0:0(4)): digit = 1
    Jul 10 01:49:16.438: //239520//Digi:/AFW_M_DigitCollect_Action:
    Jul 10 01:49:16.438: //239520//Digi:/act_DCRunning_Digit: : pLeg 239521 Digit 1 Tone Mode 0
    Jul 10 01:49:16.438: //239520//Digi:/DigitCollect_TreatDigit:
    Jul 10 01:49:16.438: //239520//Digi:/DigitCollect_DialPlanMatch: pattern offset=0, digits=13999522383451
    Jul 10 01:49:16.438: //239520//Digi:/DigitCollect_DialPlanMatch: src carrier id:, tgt carrier id:
    Jul 10 01:49:16.438: //239520//Digi:/DigitCollect_DialPlanMatch: Match single infotype
    Jul 10 01:49:16.450: htsp_process_event: [1/0:0(4), FXSLS_CONNECT, E_DSP_SIG_0100]fxsls_offhook_onhook, HF duration Max=1000, HF duration Min=150
    Jul 10 01:49:16.450: htsp_timer - 1000 msec
    Jul 10 01:49:17.451: htsp_process_event: [1/0:0(4), FXSLS_CONNECT, E_HTSP_EVENT_TIMER]fxsls_connect_wait_release_req
    Jul 10 01:49:17.451: htsp_timer_stop
    Jul 10 01:49:17.451: //239520//Digi:/AFW_M_DigitCollect_Action:
    Jul 10 01:49:17.451: //239520//Digi:/act_DCRunning_Disconnected:
    Jul 10 01:49:17.451: //-1//Digi:/DigitCollect_Complete: DC_DISCONNECTED. Digits=13999522383451
    Jul 10 01:49:17.451: //239520//TCL :/tcl_PutsObjCmd:
    Cleaning up...................
    Jul 10 01:49:17.451:
    Jul 10 01:49:17.451: //239520//TCL :/tcl_CallObjCmd:  call close
    Jul 10 01:49:17.451: //239520//TCL :/tcl_CallCloseObjCmd:  close
    Jul 10 01:49:17.451: //239520//Digi:/AFW_M_DigitCollect_EventPreProcess:
    Jul 10 01:49:17.451: //239520//Digi:/DigitCollectEnd_UpdateStats:
    Jul 10 01:49:17.451: htsp_timer_stop3
    Jul 10 01:49:17.479: htsp_process_event: [1/0:0(4), FXSLS_WAIT_RELEASE_REQ, E_HTSP_RELEASE_REQ]fxsls_waitrls_req_rlsvnm_dsp_set_sig_state:[Foreign Exchange Station 1/0:0(4)] set signal state = 0x4vnm_dsp_set_sig_state:[Foreign Exchange Station 1/0:0(4)] set signal state = 0x4
    Jul 10 01:49:17.483: htsp_process_event: [1/0:0(4), FXSLS_ONHOOK, E_DSP_SIG_0100]fxsls_onhook_onhook
    Jul 10 01:50:10.706: //237039//PACK:/DoMediaStop:
    Jul 10 01:51:22.736: %ISDN-6-CONNECT: Interface Serial0/0/0:21 is now connected to 3212004539 N/A
    q99921voipgw1#
    q99921voipgw1#
    q99921voipgw1#
    q99921voipgw1#clear log
    Clear logging buffer
    q99921voipgw1#show log
    Syslog logging: enabled (266 messages dropped, 148 messages rate-limited, 0 flushes, 0 overruns, xml disabled, filtering disabled)
     
    No Active Message Discriminator.
     
     
     
    No Inactive Message Discriminator.
     
     
        Console logging: level debugging, 1045135 messages logged, xml disabled,
                         filtering disabled
        Monitor logging: level debugging, 37099 messages logged, xml disabled,
                         filtering disabled
        Buffer logging:  level debugging, 1045251 messages logged, xml disabled,
                        filtering disabled
        Exception Logging: size (8192 bytes)
        Count and timestamp logging messages: disabled
        Persistent logging: disabled
        Trap logging: level informational, 110787 message lines logged
            Logging to 10.44.33.63  (udp port 514, audit disabled,
                  link up),
                  110787 message lines logged,
                  0 message lines rate-limited,
                  0 message lines dropped-by-MD,
                  xml disabled, sequence number disabled
                  filtering disabled
            Logging to 10.44.28.5  (udp port 514, audit disabled,
                  link up),
                  110787 message lines logged,
                  0 message lines rate-limited,
                  0 message lines dropped-by-MD,
                  xml disabled, sequence number disabled
                  filtering disabled
            Logging to 10.170.100.23  (udp port 514, audit disabled,
                  link up),
                  110787 message lines logged,
                  0 message lines rate-limited,
                  0 message lines dropped-by-MD,
                  xml disabled, sequence number disabled
                  filtering disabled
     
    Log Buffer (1024000 bytes):
     
    Jul 10 01:51:52.963: //239528//TCL :/tcl_InfotagObjCmd:  infotag get leg_isdid
    Jul 10 01:51:52.963: //239528//TCL :/tcl_InfotagGetObjCmd: infotag get leg_isdid
    Jul 10 01:51:52.963: //239528//AFW_:/vtr_lg_incdid: argc 2 argindex 2
    Jul 10 01:51:52.963: //239528//TCL :/tcl_InfotagObjCmd:  infotag get leg_dnis
    Jul 10 01:51:52.963: //239528//TCL :/tcl_InfotagGetObjCmd: infotag get leg_dnis
    Jul 10 01:51:52.963: //239528//AFW_:/vtr_lg_dnis: argc 2 argindex 2
    Jul 10 01:51:52.963: //239528//TCL :/tcl_LegObjCmd:  leg setupack leg_incoming
    Jul 10 01:51:52.963: //239528//TCL :/tcl_LegSetupAckObjCmd: setupack leg_incoming
    Jul 10 01:51:52.963: //239528//AFW_:/vtd_lg_incoming: argc 2
    Jul 10 01:51:52.963: //239528//AFW_:/vtd_lg_incoming: Legs [239528 ]
    Jul 10 01:51:52.963: //239528//Tcl :/tcl_parseCallID_vartagObj: VARTAG Translation Leg Count=1
    Jul 10 01:51:52.963: //239528//TCL :/tcl_LegObjCmd:  leg proceeding leg_incoming
    Jul 10 01:51:52.963: //239528//TCL :/tcl_LegProceedObjCmd: proceeding leg_incoming
    Jul 10 01:51:52.963: //239528//AFW_:/vtd_lg_incoming: argc 2
    Jul 10 01:51:52.963: //239528//AFW_:/vtd_lg_incoming: Legs [239528 ]
    Jul 10 01:51:52.963: //239528//Tcl :/tcl_parseCallID_vartagObj: VARTAG Translation Leg Count=1
    Jul 10 01:51:52.963: //239528//TCL :/tcl_LegObjCmd:  leg connect leg_incoming
    Jul 10 01:51:52.963: //239528//TCL :/tcl_LegConnectObjCmd: connect leg_incoming
    Jul 10 01:51:52.963: //239528//AFW_:/vtd_lg_incoming: argc 2
    Jul 10 01:51:52.963: //239528//AFW_:/vtd_lg_incoming: Legs [239528 ]
    Jul 10 01:51:52.963: //239528//Tcl :/tcl_parseCallID_vartagObj: VARTAG Translation Leg Count=1
    Jul 10 01:51:52.963: //239528//TCL :/tcl_LegObjCmd:  leg setup sip:19528284207@10.170.47.11:5060 callInfo leg_incoming
    Jul 10 01:51:52.963: //239528//AFW_:/vtd_lg_incoming: argc 4
    Jul 10 01:51:52.963: //239528//AFW_:/vtd_lg_incoming: Legs [239528 ]
    Jul 10 01:51:52.963: //239528//Tcl :/tcl_parseCallID_vartagObj: VARTAG Translation Leg Count=1
    Jul 10 01:51:52.963: htsp_timer_stop3 htsp_setup_req
    Jul 10 01:51:52.965: htsp_process_event: [1/0:0(1), FXSLS_ONHOOK, E_HTSP_SETUP_REQ]fxsls_onhook_setuphtsp_alertvnm_dsp_set_sig_state:[Foreign Exchange Station 1/0:0(1)] set signal state = 0x0
    Jul 10 01:51:52.965: htsp_call_bridged invoked
    Jul 10 01:51:52.965: htsp_process_event: [1/0:0(1), FXSLS_WAIT_OFFHOOK, E_HTSP_VOICE_CUT_THROUGH]fxsls_waitoff_voice
    Jul 10 01:51:55.013: htsp_process_event: [1/0:0(1), FXSLS_WAIT_OFFHOOK, E_DSP_SIG_1100]fxsls_waitoff_offhookvnm_dsp_set_sig_state:[Foreign Exchange Station 1/0:0(1)] set signal state = 0x4vnm_dsp_set_sig_state:[Foreign Exchange Station 1/0:0(1)] set signal state = 0x6
    Jul 10 01:51:55.013: htsp_timer2 - 200 msec
    Jul 10 01:51:55.213: htsp_process_event: [1/0:0(1), FXSLS_WAIT_OFFHOOK, E_HTSP_EVENT_TIMER2]fxsls_offhook_dial htsp_dial
    Jul 10 01:51:55.213: htsp_process_event: [1/0:0(1), FXSLS_CONNECT, E_DSP_DIALING_DONE]fxsls_conn_dial_done
    Jul 10 01:51:55.213: //239528//TCL :/tcl_InfotagObjCmd:  infotag get evt_status
    Jul 10 01:51:55.213: //239528//TCL :/tcl_InfotagGetObjCmd: infotag get evt_status
    Jul 10 01:51:55.213: //239528//AFW_:/vtr_ev_status: argc 2 argindex 2
    Jul 10 01:51:55.213: //239528//TCL :/tcl_PutsObjCmd:
    Call to Number successful
    Jul 10 01:51:55.213:
    Jul 10 01:51:55.213: //239528//TCL :/tcl_InfotagObjCmd:  infotag get leg_all
    Jul 10 01:51:55.213: //239528//TCL :/tcl_InfotagGetObjCmd: infotag get leg_all
    Jul 10 01:51:55.213: //239528//AFW_:/vtr_lg_all: argc 2
    Jul 10 01:51:55.213: //239528//TCL :/tcl_LegObjCmd:  leg collectdigits 239528 239529 dcparams
    Jul 10 01:51:55.213: //239528//Digi:/tcl_LegDigitCollectObjCmd: collectdigits 239528 239529 dcparams
    Jul 10 01:51:55.213: //239528//Tcl :/tcl_parseCallID_vartagObj: VARTAG Translation Leg Count=2
    Jul 10 01:51:55.213: //239528//Digi:/C_DigitCollect_Start: Leg=239528, Dialplan=False, Diaplanterm=False, DigitReport=True, DigitConsume=False IgnoreInitialKey=False, IgnoreDTMFacceptINFO=False, Abortkey=^@, Terminationkey=^@, Numpatterns=0, Maxdigits=0, Mindigits=0, Interruptprompt=False, InterTimeout=-1000, Initialtimeout=-1000, Mask=0 Hotword=0
    Jul 10 01:51:55.213: //-1//Digi:/AFW_DigitCollect_New:
    Jul 10 01:51:55.213: //-1//Digi:HNCD51947E:/AFW_DigitCollect_New: DialPlan=FALSE AbortKey=^@ TermKey=^@ NumPatts=0
                  Enable=TRUE Consume=FALSE InterruptPrompt=FALSE minDigits=0 maxDigits=0 DialPlanTerm=FALSE hotword=0
    Jul 10 01:51:55.213: //239528/D09671800006/Digi:/DigitCollectStart_UpdateStats:
    Jul 10 01:51:55.213: //239528//Digi:/DigitCollect_MLPPTuning:
    Jul 10 01:51:55.213: //239528//Digi:/DigitCollect_MLPPTuning: Precednece Digit Collect not enabled
    Jul 10 01:51:55.213: //239528//Digi:/C_DigitCollect_Start: Leg=239529, Dialplan=False, Diaplanterm=False, DigitReport=True, DigitConsume=False IgnoreInitialKey=False, IgnoreDTMFacceptINFO=False, Abortkey=^@, Terminationkey=^@, Numpatterns=0, Maxdigits=0, Mindigits=0, Interruptprompt=False, InterTimeout=-1000, Initialtimeout=-1000, Mask=0 Hotword=0
    Jul 10 01:51:55.213: //-1//Digi:/AFW_DigitCollect_New:
    Jul 10 01:51:55.213: //-1//Digi:HNCD51947E:/AFW_DigitCollect_New: DialPlan=FALSE AbortKey=^@ TermKey=^@ NumPatts=0
                  Enable=TRUE Consume=FALSE InterruptPrompt=FALSE minDigits=0 maxDigits=0 DialPlanTerm=FALSE hotword=0
    Jul 10 01:51:55.213: //239529/D09671800006/Digi:/DigitCollectStart_UpdateStats:
    Jul 10 01:51:55.213: //239528//Digi:/DigitCollect_MLPPTuning:
    Jul 10 01:51:55.213: //239528//Digi:/DigitCollect_MLPPTuning: Precednece Digit Collect not enabled
    Jul 10 01:51:55.213: //239528//Digi:/AFW_M_DigitCollect_Action:
    Jul 10 01:51:55.213: //239528//Digi:/act_DCRunning_RDone: id=239528 Enable succeeded.enable=1 matchDialplan=0 numPatterns=0matchDialplanTerm=0
    Jul 10 01:51:55.213: //-1//Digi:/DigitCollect_Complete: DC_ENABLED. Digits=
    Jul 10 01:51:55.213: //239528//Digi:/AFW_M_DigitCollect_EventPreProcess:
    Jul 10 01:51:55.213: //239528//Digi:/DigitCollectEnd_UpdateStats:
    Jul 10 01:51:55.213: //239528//Digi:/AFW_M_DigitCollect_Action:
    Jul 10 01:51:55.213: //239528//Digi:/act_DCRunning_RDone: id=239529 Enable succeeded.enable=1 matchDialplan=0 numPatterns=0matchDialplanTerm=0
    Jul 10 01:51:55.213: //-1//Digi:/DigitCollect_Complete: DC_ENABLED. Digits=
    Jul 10 01:51:55.213: //239528//Digi:/AFW_M_DigitCollect_EventPreProcess:
    Jul 10 01:51:55.213: //239528//Digi:/DigitCollectEnd_UpdateStats:
    Jul 10 01:52:31.588: htsp_process_event: [1/0:0(1), FXSLS_CONNECT, E_DSP_SIG_0100]fxsls_offhook_onhook, HF duration Max=1000, HF duration Min=150
    Jul 10 01:52:31.588: htsp_timer - 1000 msec
    Jul 10 01:52:32.190: htsp_process_event: [1/0:0(1), FXSLS_CONNECT, E_DSP_SIG_1100]fxsls_offhook_offhookhtsp_hook_flash_ind
    Jul 10 01:52:32.190: htsp_timer_stop
    Jul 10 01:52:32.577: htsp_digit_ready(1/0:0(1)): digit = 1
    Jul 10 01:52:32.737: htsp_digit_ready(1/0:0(1)): digit = 3
    Jul 10 01:52:32.897: htsp_digit_ready(1/0:0(1)): digit = 9
    Jul 10 01:52:33.029: htsp_digit_ready(1/0:0(1)): digit = 9
    Jul 10 01:52:33.191: htsp_digit_ready(1/0:0(1)): digit = 9
    Jul 10 01:52:33.349: htsp_digit_ready(1/0:0(1)): digit = 5
    Jul 10 01:52:33.509: htsp_digit_ready(1/0:0(1)): digit = 2
    Jul 10 01:52:33.669: htsp_digit_ready(1/0:0(1)): digit = 2
    q99921voipgw1#show log
    Syslog logging: enabled (266 messages dropped, 148 messages rate-limited, 0 flushes, 0 overruns, xml disabled, filtering disabled)
     
    No Active Message Discriminator.
     
     
     
    No Inactive Message Discriminator.
     
     
        Console logging: level debugging, 1045171 messages logged, xml disabled,
                         filtering disabled
        Monitor logging: level debugging, 37099 messages logged, xml disabled,
                         filtering disabled
        Buffer logging:  level debugging, 1045287 messages logged, xml disabled,
                        filtering disabled
        Exception Logging: size (8192 bytes)
        Count and timestamp logging messages: disabled
        Persistent logging: disabled
        Trap logging: level informational, 110787 message lines logged
            Logging to 10.44.33.63  (udp port 514, audit disabled,
                  link up),
                  110787 message lines logged,
                  0 message lines rate-limited,
                  0 message lines dropped-by-MD,
                  xml disabled, sequence number disabled
                  filtering disabled
            Logging to 10.44.28.5  (udp port 514, audit disabled,
                  link up),
                  110787 message lines logged,
                  0 message lines rate-limited,
                  0 message lines dropped-by-MD,
                  xml disabled, sequence number disabled
                  filtering disabled
            Logging to 10.170.100.23  (udp port 514, audit disabled,
                  link up),
                  110787 message lines logged,
                  0 message lines rate-limited,
                  0 message lines dropped-by-MD,
                  xml disabled, sequence number disabled
                  filtering disabled
     
    Log Buffer (1024000 bytes):
     
    Jul 10 01:51:52.963: //239528//TCL :/tcl_InfotagObjCmd:  infotag get leg_isdid
    Jul 10 01:51:52.963: //239528//TCL :/tcl_InfotagGetObjCmd: infotag get leg_isdid
    Jul 10 01:51:52.963: //239528//AFW_:/vtr_lg_incdid: argc 2 argindex 2
    Jul 10 01:51:52.963: //239528//TCL :/tcl_InfotagObjCmd:  infotag get leg_dnis
    Jul 10 01:51:52.963: //239528//TCL :/tcl_InfotagGetObjCmd: infotag get leg_dnis
    Jul 10 01:51:52.963: //239528//AFW_:/vtr_lg_dnis: argc 2 argindex 2
    Jul 10 01:51:52.963: //239528//TCL :/tcl_LegObjCmd:  leg setupack leg_incoming
    Jul 10 01:51:52.963: //239528//TCL :/tcl_LegSetupAckObjCmd: setupack leg_incoming
    Jul 10 01:51:52.963: //239528//AFW_:/vtd_lg_incoming: argc 2
    Jul 10 01:51:52.963: //239528//AFW_:/vtd_lg_incoming: Legs [239528 ]
    Jul 10 01:51:52.963: //239528//Tcl :/tcl_parseCallID_vartagObj: VARTAG Translation Leg Count=1
    Jul 10 01:51:52.963: //239528//TCL :/tcl_LegObjCmd:  leg proceeding leg_incoming
    Jul 10 01:51:52.963: //239528//TCL :/tcl_LegProceedObjCmd: proceeding leg_incoming
    Jul 10 01:51:52.963: //239528//AFW_:/vtd_lg_incoming: argc 2
    Jul 10 01:51:52.963: //239528//AFW_:/vtd_lg_incoming: Legs [239528 ]
    Jul 10 01:51:52.963: //239528//Tcl :/tcl_parseCallID_vartagObj: VARTAG Translation Leg Count=1
    Jul 10 01:51:52.963: //239528//TCL :/tcl_LegObjCmd:  leg connect leg_incoming
    Jul 10 01:51:52.963: //239528//TCL :/tcl_LegConnectObjCmd: connect leg_incoming
    Jul 10 01:51:52.963: //239528//AFW_:/vtd_lg_incoming: argc 2
    Jul 10 01:51:52.963: //239528//AFW_:/vtd_lg_incoming: Legs [239528 ]
    Jul 10 01:51:52.963: //239528//Tcl :/tcl_parseCallID_vartagObj: VARTAG Translation Leg Count=1
    Jul 10 01:51:52.963: //239528//TCL :/tcl_LegObjCmd:  leg setup sip:19528284207@10.170.47.11:5060 callInfo leg_incoming
    Jul 10 01:51:52.963: //239528//AFW_:/vtd_lg_incoming: argc 4
    Jul 10 01:51:52.963: //239528//AFW_:/vtd_lg_incoming: Legs [239528 ]
    Jul 10 01:51:52.963: //239528//Tcl :/tcl_parseCallID_vartagObj: VARTAG Translation Leg Count=1
    Jul 10 01:51:52.963: htsp_timer_stop3 htsp_setup_req
    Jul 10 01:51:52.965: htsp_process_event: [1/0:0(1), FXSLS_ONHOOK, E_HTSP_SETUP_REQ]fxsls_onhook_setuphtsp_alertvnm_dsp_set_sig_state:[Foreign Exchange Station 1/0:0(1)] set signal state = 0x0
    Jul 10 01:51:52.965: htsp_call_bridged invoked
    Jul 10 01:51:52.965: htsp_process_event: [1/0:0(1), FXSLS_WAIT_OFFHOOK, E_HTSP_VOICE_CUT_THROUGH]fxsls_waitoff_voice
    Jul 10 01:51:55.013: htsp_process_event: [1/0:0(1), FXSLS_WAIT_OFFHOOK, E_DSP_SIG_1100]fxsls_waitoff_offhookvnm_dsp_set_sig_state:[Foreign Exchange Station 1/0:0(1)] set signal state = 0x4vnm_dsp_set_sig_state:[Foreign Exchange Station 1/0:0(1)] set signal state = 0x6
    Jul 10 01:51:55.013: htsp_timer2 - 200 msec
    Jul 10 01:51:55.213: htsp_process_event: [1/0:0(1), FXSLS_WAIT_OFFHOOK, E_HTSP_EVENT_TIMER2]fxsls_offhook_dial htsp_dial
    Jul 10 01:51:55.213: htsp_process_event: [1/0:0(1), FXSLS_CONNECT, E_DSP_DIALING_DONE]fxsls_conn_dial_done
    Jul 10 01:51:55.213: //239528//TCL :/tcl_InfotagObjCmd:  infotag get evt_status
    Jul 10 01:51:55.213: //239528//TCL :/tcl_InfotagGetObjCmd: infotag get evt_status
    Jul 10 01:51:55.213: //239528//AFW_:/vtr_ev_status: argc 2 argindex 2
    Jul 10 01:51:55.213: //239528//TCL :/tcl_PutsObjCmd:
    Call to Number successful
    Jul 10 01:51:55.213:
    Jul 10 01:51:55.213: //239528//TCL :/tcl_InfotagObjCmd:  infotag get leg_all
    Jul 10 01:51:55.213: //239528//TCL :/tcl_InfotagGetObjCmd: infotag get leg_all
    Jul 10 01:51:55.213: //239528//AFW_:/vtr_lg_all: argc 2
    Jul 10 01:51:55.213: //239528//TCL :/tcl_LegObjCmd:  leg collectdigits 239528 239529 dcparams
    Jul 10 01:51:55.213: //239528//Digi:/tcl_LegDigitCollectObjCmd: collectdigits 239528 239529 dcparams
    Jul 10 01:51:55.213: //239528//Tcl :/tcl_parseCallID_vartagObj: VARTAG Translation Leg Count=2
    Jul 10 01:51:55.213: //239528//Digi:/C_DigitCollect_Start: Leg=239528, Dialplan=False, Diaplanterm=False, DigitReport=True, DigitConsume=False IgnoreInitialKey=False, IgnoreDTMFacceptINFO=False, Abortkey=^@, Terminationkey=^@, Numpatterns=0, Maxdigits=0, Mindigits=0, Interruptprompt=False, InterTimeout=-1000, Initialtimeout=-1000, Mask=0 Hotword=0
    Jul 10 01:51:55.213: //-1//Digi:/AFW_DigitCollect_New:
    Jul 10 01:51:55.213: //-1//Digi:HNCD51947E:/AFW_DigitCollect_New: DialPlan=FALSE AbortKey=^@ TermKey=^@ NumPatts=0
                  Enable=TRUE Consume=FALSE InterruptPrompt=FALSE minDigits=0 maxDigits=0 DialPlanTerm=FALSE hotword=0
    Jul 10 01:51:55.213: //239528/D09671800006/Digi:/DigitCollectStart_UpdateStats:
    Jul 10 01:51:55.213: //239528//Digi:/DigitCollect_MLPPTuning:
    Jul 10 01:51:55.213: //239528//Digi:/DigitCollect_MLPPTuning: Precednece Digit Collect not enabled
    Jul 10 01:51:55.213: //239528//Digi:/C_DigitCollect_Start: Leg=239529, Dialplan=False, Diaplanterm=False, DigitReport=True, DigitConsume=False IgnoreInitialKey=False, IgnoreDTMFacceptINFO=False, Abortkey=^@, Terminationkey=^@, Numpatterns=0, Maxdigits=0, Mindigits=0, Interruptprompt=False, InterTimeout=-1000, Initialtimeout=-1000, Mask=0 Hotword=0
    Jul 10 01:51:55.213: //-1//Digi:/AFW_DigitCollect_New:
    Jul 10 01:51:55.213: //-1//Digi:HNCD51947E:/AFW_DigitCollect_New: DialPlan=FALSE AbortKey=^@ TermKey=^@ NumPatts=0
                  Enable=TRUE Consume=FALSE InterruptPrompt=FALSE minDigits=0 maxDigits=0 DialPlanTerm=FALSE hotword=0
    Jul 10 01:51:55.213: //239529/D09671800006/Digi:/DigitCollectStart_UpdateStats:
    Jul 10 01:51:55.213: //239528//Digi:/DigitCollect_MLPPTuning:
    Jul 10 01:51:55.213: //239528//Digi:/DigitCollect_MLPPTuning: Precednece Digit Collect not enabled
    Jul 10 01:51:55.213: //239528//Digi:/AFW_M_DigitCollect_Action:
    Jul 10 01:51:55.213: //239528//Digi:/act_DCRunning_RDone: id=239528 Enable succeeded.enable=1 matchDialplan=0 numPatterns=0matchDialplanTerm=0
    Jul 10 01:51:55.213: //-1//Digi:/DigitCollect_Complete: DC_ENABLED. Digits=
    Jul 10 01:51:55.213: //239528//Digi:/AFW_M_DigitCollect_EventPreProcess:
    Jul 10 01:51:55.213: //239528//Digi:/DigitCollectEnd_UpdateStats:
    Jul 10 01:51:55.213: //239528//Digi:/AFW_M_DigitCollect_Action:
    Jul 10 01:51:55.213: //239528//Digi:/act_DCRunning_RDone: id=239529 Enable succeeded.enable=1 matchDialplan=0 numPatterns=0matchDialplanTerm=0
    Jul 10 01:51:55.213: //-1//Digi:/DigitCollect_Complete: DC_ENABLED. Digits=
    Jul 10 01:51:55.213: //239528//Digi:/AFW_M_DigitCollect_EventPreProcess:
    Jul 10 01:51:55.213: //239528//Digi:/DigitCollectEnd_UpdateStats:
    Jul 10 01:52:31.588: htsp_process_event: [1/0:0(1), FXSLS_CONNECT, E_DSP_SIG_0100]fxsls_offhook_onhook, HF duration Max=1000, HF duration Min=150
    Jul 10 01:52:31.588: htsp_timer - 1000 msec
    Jul 10 01:52:32.190: htsp_process_event: [1/0:0(1), FXSLS_CONNECT, E_DSP_SIG_1100]fxsls_offhook_offhookhtsp_hook_flash_ind
    Jul 10 01:52:32.190: htsp_timer_stop
    Jul 10 01:52:32.577: htsp_digit_ready(1/0:0(1)): digit = 1
    Jul 10 01:52:32.737: htsp_digit_ready(1/0:0(1)): digit = 3
    Jul 10 01:52:32.897: htsp_digit_ready(1/0:0(1)): digit = 9
    Jul 10 01:52:33.029: htsp_digit_ready(1/0:0(1)): digit = 9
    Jul 10 01:52:33.191: htsp_digit_ready(1/0:0(1)): digit = 9
    Jul 10 01:52:33.349: htsp_digit_ready(1/0:0(1)): digit = 5
    Jul 10 01:52:33.509: htsp_digit_ready(1/0:0(1)): digit = 2
    Jul 10 01:52:33.669: htsp_digit_ready(1/0:0(1)): digit = 2
    Jul 10 01:52:33.829: htsp_digit_ready(1/0:0(1)): digit = 3
    Jul 10 01:52:33.989: htsp_digit_ready(1/0:0(1)): digit = 8
    Jul 10 01:52:34.149: htsp_digit_ready(1/0:0(1)): digit = 3
    Jul 10 01:52:34.309: htsp_digit_ready(1/0:0(1)): digit = 4
    Jul 10 01:52:34.469: htsp_digit_ready(1/0:0(1)): digit = 5
    Jul 10 01:52:34.629: htsp_digit_ready(1/0:0(1)): digit = 1
    Jul 10 01:52:34.637: htsp_process_event: [1/0:0(1), FXSLS_CONNECT, E_DSP_SIG_0100]fxsls_offhook_onhook, HF duration Max=1000, HF duration Min=150
    Jul 10 01:52:34.637: htsp_timer - 1000 msec
    Jul 10 01:52:35.637: htsp_process_event: [1/0:0(1), FXSLS_CONNECT, E_HTSP_EVENT_TIMER]fxsls_connect_wait_release_req
    Jul 10 01:52:35.637: htsp_timer_stop
    Jul 10 01:52:35.637: //239528//TCL :/tcl_PutsObjCmd:
    Cleaning up...................
    Jul 10 01:52:35.637:
    Jul 10 01:52:35.637: //239528//TCL :/tcl_CallObjCmd:  call close
    Jul 10 01:52:35.637: //239528//TCL :/tcl_CallCloseObjCmd:  close
    Jul 10 01:52:35.637: htsp_timer_stop3
    Jul 10 01:52:35.669: htsp_process_event: [1/0:0(1), FXSLS_WAIT_RELEASE_REQ, E_HTSP_RELEASE_REQ]fxsls_waitrls_req_rlsvnm_dsp_set_sig_state:[Foreign Exchange Station 1/0:0(1)] set signal state = 0x4vnm_dsp_set_sig_state:[Foreign Exchange Station 1/0:0(1)] set signal state = 0x4
    Jul 10 01:52:35.673: htsp_process_event: [1/0:0(1), FXSLS_ONHOOK, E_DSP_SIG_0100]fxsls_onhook_onhook
     

     
     

    Subject: RE: TCL ev_feature event inconsistent
    Replied by: Yaw-Ming Chen on 23-07-2012 01:59:45 PM
    I wonder how the call can be established?

    Looks like the incoming leg is SIP
    Jul 10 01:48:42.162: //239520//TCL :/tcl_LegObjCmd:  leg setup sip:19528284207@10.170.47.11:5060 callInfo leg_incoming

    Let setup command only takes digits, so before the leg setup you may want to extract the calling number like
    regexp {[0-9]+} $dnis dnis

    Subject: RE: TCL ev_feature event inconsistent
    Replied by: James Clapper on 23-07-2012 04:30:57 PM
    Thats a good question. It does however connect as you can see. Also get the IVR recording and status code is ls_000. Shouldn't this fail actually?
    Will try and pull out the DNIS and see if that is the core of my issue.

    These are my dial-peers:

    dial-peer voice 4207 voip
    service cast1hookflash
    incoming called-number 19528284207
    dtmf-relay rtp-nte digit-drop h245-alphanumeric

    dial-peer voice 4208 pots
    destination-pattern 19528284207
    port 1/0:0
    forward-digits 0

    Subject: RE: TCL ev_feature event inconsistent
    Replied by: James Clapper on 23-07-2012 04:46:22 PM
    Got the digits only by adding the regex.

        regexp {[0-9]{11}} $dest dest
        leg setup $dest callInfo leg_incoming

    Still works, but same issue as before. Only seeing the hookflash event every once and a while.

    Subject: RE: TCL ev_feature event inconsistent
    Replied by: Yaw-Ming Chen on 23-07-2012 05:01:40 PM
    Also put "infotag set evt_feature_report hookflash" in the beginning of act_setup procedure see if it helps.

    Subject: RE: TCL ev_feature event inconsistent
    Replied by: James Clapper on 24-07-2012 08:48:14 PM
    That did it! Hey thanks much. Guess it makes sense not to have it in init if I think about it.