authentication problem

Version 1
    This document was generated from CDN thread

    Created by: WESLEY PHILLIPS on 27-06-2011 05:48:04 PM
    I am trying to run a script on a voice gateway. The script runs when the call arrives, and the processing runs as expectedx until it gets to the act_Authenticated subroutine. Here is the act_Authenticated routine:
     
    proc act_Authenticated { } {
        global param1
        global param
        global dnis
        global fcnt
        global retryCnt
     
        set status [infotag get evt_status]
        puts "\n@@@@status=$status"
        if { ($status == "au_000") ||
             ($status == "au_001") } {
     
            leg setup $dnis callInfo leg_incoming
            fsm setstate  PLACECALL
            return 
        } else {
     
            leg setup 18001234567 callInfo leg_incoming
            fsm setstate PLACECALL
        }
     
    }
     
    I want the script to place the call when the radius server retuens an authentication success ("au_000") and also then the radius server is unavailable("au_001"), and redirect to a different number on authentication failure. The problem I am having is when the radius server is unavailable. The authentication fails as expected, and the script tries to set up the outbound call leg, but I get the following error after the leg setup command is executed:
     
    Jun 24 16:08:59.955: //-1//AFW_:/AFW_Util_GetTgCicValue: CIC Not  found for tag(56)
    Jun 24 16:08:59.955: //4074//OSP :/Dest_Settlement_MatrixCheck: retcode=2 cid(4074) trans=0x0, provider=0 User is not authenticated and not roaming
    Jun 24 16:08:59.955: %VOICE_IEC-3-GW: C SCRIPTS: Internal Error (OSP Fail): IEC=1.1.228.11.32.0 on callID 4074 GUID=3BC7C2049DB311E081A59A670DD4F946
     
    Is there a variable that I can change to make the script think that the authentication succeeded in this scenario so that the call will complete? The aaa command that I am using is "aaa authenticate" command, which shouldn't return any AV pairs, so I am at a loss as to why the calls will not complete. Any help would be appreciated.
     
    thanks

    Subject: RE: authentication problem
    Replied by: WESLEY PHILLIPS on 28-06-2011 09:27:53 AM
    here is the full script:


    proc init { } {
        global param
        global param1
        global retryCnt

        set param(interruptPrompt) true
        set param(abortKey) *
        set param(terminationKey) #

        set param1(interruptPrompt) true
        set param1(abortKey) *
        set param1(terminationKey) #
        set param1(dialPlan) true

        if { [infotag get cfg_avpair_exists retry-count] } {
            set retryCnt [infotag get cfg_avpair retry-count]
        } else {
            set retryCnt 3
        }

    }
    proc init_perCallVars { } {
        global beep
        global fcnt
       
        set fcnt 0
        set beep 0
       
    }
    proc act_Setup { } {
        global dnis

        init_perCallVars

        leg setupack leg_incoming
        leg proceeding leg_incoming
        leg connect leg_incoming
        set ani [infotag get leg_ani]
        set dnis [infotag get leg_dnis]
       
        aaa authenticate $ani $dnis
       
    }

    proc act_Authenticated { } {
        global param1
        global param
        global dnis
        global fcnt
        global retryCnt

        set status [infotag get evt_status]
        puts "\n@@@@status=$status"
        if { ($status == "au_000") ||
             ($status == "au_001") } {

            leg setup $dnis callInfo leg_incoming
            fsm setstate  PLACECALL
            return
        } else {

            leg setup 8326682500 callInfo leg_incoming
            fsm setstate PLACECALL
        }
       
    }

    proc act_PromptCollect_acct { } {
        global account
        global param
        global fcnt

        set status [infotag get evt_status]
        if { ($status == "cd_002") ||
             ($status == "cd_007") ||
             ($status == "cd_001") ||
             ($status == "cd_006") } {

            #enter account NO:
            set pattern(account) .+

            leg collectdigits leg_incoming param pattern
            if { $fcnt == 0 } {
                media play leg_incoming flash:enter_account.au
            } else {
                media play leg_incoming flash:auth_fail_retry.au
            }

            fsm setstate samestate
            return
        }

       
        if {$status == "cd_005"} {
            set account [infotag get evt_dcdigits]

            set pattern(account) .+
               
            leg collectdigits leg_incoming param pattern
            media play leg_incoming flash:enter_pin.au
        }

    }

    proc act_PromptCollect_pass { } {
        global pin
        global account
        global param
        global fcnt

        set status [infotag get evt_status]
        #Aborted
        if {$status == "cd_002"} {
            #enter account NO:
            set pattern(account) .+

            leg collectdigits leg_incoming param pattern
            if { $fcnt == 0 } {
                media play leg_incoming flash:enter_account.au
            } else {
                media play leg_incoming flash:auth_fail_retry.au
            }
            fsm setstate  GETACCOUNT
            return
        }

        #timeout/invalid number
        if { ($status == "cd_001") ||
             ($status == "cd_006") ||
             ($status == "cd_007") } {
            set pattern(account) .+
               
            leg collectdigits leg_incoming param pattern
            media play leg_incoming flash:enter_pin.au
            fsm setstate  samestate
            return
        }

        if {$status == "cd_005"} {
            set pin [infotag get evt_dcdigits]

            aaa authenticate $account $pin

        }
       
    }

    proc act_PromptCollect_dest { } {
        global dest
        global param1

        set status [infotag get evt_status]

        #Aborted/Invalid
        if { ($status == "cd_002") ||
             ($status == "cd_006") ||
             ($status == "cd_001") ||
             ($status == "cd_007")} {

            set param(dialPlan) true
            leg collectdigits leg_incoming param1
            media play leg_incoming flash:enter_destination.au
            fsm setstate GETDEST
            return
        }
        #matched dialplan
        if {$status == "cd_004"} {
            set dest [infotag get evt_dcdigits]
            leg setup $dest callInfo leg_incoming
        }
       
    }

    proc act_CallSetupDone { } {
        global beep
        set status [infotag get evt_status]

        if { $status == "ls_000"} {

            set  creditTimeLeft "unlimited"
            if { $creditTimeLeft == "unlimited" } {
                puts "\n Unlimited Time"
            } else {
                # start the timer for ...
                if { $creditTimeLeft < 10 } {
                    set beep 1
                    set delay $creditTimeLeft
                } else {
                    set delay [expr $creditTimeLeft - 10]
                }
                timer start leg_timer $delay leg_incoming
            }
        } else {
            set tone [infotag get evt_status]
            playtone leg_incoming $tone
            timer start leg_timer 5 leg_incoming
            fsm setstate CALLDISCONNECT 
        }
    }

    proc act_Timer { } {
        global beep
        global incoming
        global outgoing

        set incoming [infotag get leg_incoming]
        set outgoing [infotag get leg_outgoing]
       
        if { $beep == 0 } {
            #insert a beep ...to the caller
            connection destroy con_all
            set beep 1
        } else {
            connection destroy con_all
            fsm setstate LASTWARN
        }
    }

    proc act_LastWarn { } {
        media play leg_incoming flash:out_of_time.au
    }

    proc act_Destroy { } {
        media play leg_incoming flash:beep.au
    }

    proc act_Beeped { } {
        global incoming
        global outgoing

        connection create $incoming $outgoing
    }

    proc act_ConnectedAgain { } {
        #get the timer value again and start the timer ???
        #set delay [infotag get VARTAG]
        timer start leg_timer 10 leg_incoming
    }

    proc act_Ignore { } {
    # Dummy
        puts "Event Capture"
    }

    proc act_Cleanup { } {
        call close
    }

    requiredversion 2.0
    init


    #----------------------------------
    #   State Machine
    #----------------------------------

      set fsm(any_state,ev_disconnected) "act_Cleanup,samestate"
      set fsm(CALL_INIT,ev_setup_indication)   "act_Setup   AUTHENTICATE"

      set fsm(AUTHENTICATE,ev_authenticate_done)  "act_Authenticated  GETDEST"

      set fsm(GETACCOUNT,ev_collectdigits_done)  "act_PromptCollect_acct GETPASSWORD"
      set fsm(GETPASSWORD,ev_collectdigits_done) "act_PromptCollect_pass AUTHENTICATE"

      set fsm(GETDEST,ev_collectdigits_done) "act_PromptCollect_dest PLACECALL"

      set fsm(PLACECALL,ev_setup_done)      "act_CallSetupDone      CALLACTIVE"

      set fsm(CALLACTIVE,ev_leg_timer)      "act_Timer            INSERTBEEP"
      set fsm(INSERTBEEP,ev_destroy_done)   "act_Destroy          samestate"
      set fsm(INSERTBEEP,ev_media_done)     "act_Beeped           samestate"
      set fsm(INSERTBEEP,ev_create_done)    "act_ConnectedAgain   CALLACTIVE"
     
      set fsm(LASTWARN,ev_destroy_done)     "act_LastWarn        CALLDISCONNECT"

      set fsm(CALLACTIVE,ev_disconnected)   "act_Cleanup          CALLDISCONNECT"
      set fsm(CALLDISCONNECT,ev_media_done) "act_Cleanup          samestate"
      set fsm(CALLDISCONNECT,ev_disconnect_done) "act_Cleanup     samestate"
      set fsm(CALLDISCONNECT,ev_leg_timer)       "act_Cleanup     samestate"


      fsm define fsm CALL_INIT


    and here is the output of the call with the requested debugs:

    Jun 28 13:29:22.048: //-1//SCRI:/ScriptList_CacheCurrent:  auth
    Jun 28 13:30:17.996: //4107/CD699A0981E7/VAAA:0/voip_start_ccapi_accounting: WARNING: gw-accounting aaa not enabled. return.
    Jun 28 13:30:17.996: //-1//SERV:/AFW_Service_CCInterface: Received Event 25 for service auth modulehandle NULL
    Jun 28 13:30:17.996: //-1//SERV:/AFW_Service_GetExecEnv: Script Name = auth
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_Process_New: auth
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: Process(Size=128)
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x30E813F4, Type: ProcManager, RefCount: 2
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_ExecEnv_New: 
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: ExecEnv(Size=232)
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_DataArray_New: 
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataArray(Size=80)
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_DataArray_New: 
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataArray(Size=80)
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_DataArray_New: 
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataArray(Size=80)
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_DataArray_New: 
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataArray(Size=80)
    Jun 28 13:30:17.996: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_SetRoot: Execenv = 0x31D29988
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_TclModule_New: 
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: TclModule(Size=368)
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_DataArray_New: 
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataArray(Size=80)
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_Process_Lock: pProcess(0x3144780C)=1
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x3144780C, Type: Process, RefCount: 2
    Jun 28 13:30:17.996: //-1//AFW_:LP:EE31D29988000:HN1EC3E108:/AFW_M_Object_SetExecEnv: ObjCount: 1, CmdPending 0
    Jun 28 13:30:17.996: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_SetScript:  Script Name = auth,
    Jun 28 13:30:17.996: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_SetScript:     Script URI = http://172.17.2.10/auth.tcl
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_PackTable_New:  
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: PackTable(Size=36)
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_PackTable_SetSettings: 
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_PackTable_SetScript: 
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x30E80C10, Type: Service, RefCount: 3
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_PackTable_SetParamArray: 
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x31CE4834, Type: DataArray, RefCount: 3
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_DataArray_ElementSet: Adding param: auth, type: PackTable
    Jun 28 13:30:17.996: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:  Script Name = auth,
    Jun 28 13:30:17.996: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script URI = http://172.17.2.10/auth.tcl
    Jun 28 13:30:17.996: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script type = Tcl Script
    Jun 28 13:30:17.996: //-1//AFW_:EE31D29988000:/Tcl_Link: Linking script auth
    Jun 28 13:30:17.996: //-1//PACK:EE31D29988000:/PkgRequire:  name(tcl20base) version() exact(0) rootScript(auth)
    Jun 28 13:30:17.996: //-1//PACK:/find_global_package_entry:  pkgName(tcl20base) exact(0)
    Jun 28 13:30:17.996: //-1//PACK:EE31D29988000:/PkgRequire:  Linking package tcl20base
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_PackTable_New:  
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: PackTable(Size=36)
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_PackTable_SetVersion: 
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_PackTable_SetVersion:  setting version 1.0 for the package
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_PackTable_SetSettings: 
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_PackTable_SetScript: 
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x296EDC34, Type: Package, RefCount: 16
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_DataArray_ElementSet: Adding param: tcl20base, type: PackTable
    Jun 28 13:30:17.996: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:  Script Name = tcl20base,
    Jun 28 13:30:17.996: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script URI = builtin:tcl20base_package.C
    Jun 28 13:30:17.996: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script type = C Script
    Jun 28 13:30:17.996: //-1//PACK:EE31D29988000:/PkgProvide:  name(tcl20base) version(1.0) rootScript(auth)
    Jun 28 13:30:17.996: //-1//PACK:/ComparePkgVersions:  v1(1.0) v2(1.0)
    Jun 28 13:30:17.996: //-1//PACK:EE31D29988000:/PkgRequire:  name(tclcore) version() exact(0) rootScript(auth)
    Jun 28 13:30:17.996: //-1//PACK:/find_global_package_entry:  pkgName(tclcore) exact(0)
    Jun 28 13:30:17.996: //-1//PACK:EE31D29988000:/PkgRequire:  Linking package tclcore
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_PackTable_New:  
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: PackTable(Size=36)
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_PackTable_SetVersion: 
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_PackTable_SetVersion:  setting version 1.0 for the package
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_PackTable_SetSettings: 
    Jun 28 13:30:17.996: //-1//AFW_:/AFW_PackTable_SetScript: 
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x296EDA14, Type: Package, RefCount: 20
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_DataArray_ElementSet: Adding param: tclcore, type: PackTable
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:  Script Name = tclcore,
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script URI = builtin:tclcore_package.C
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script type = C Script
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgProvide:  name(tclcore) version(1.0) rootScript(auth)
    Jun 28 13:30:18.000: //-1//PACK:/ComparePkgVersions:  v1(1.0) v2(1.0)
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgRequire:  name(tclmodule) version() exact(0) rootScript(auth)
    Jun 28 13:30:18.000: //-1//PACK:/find_global_package_entry:  pkgName(tclmodule) exact(0)
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgRequire:  Linking package tclmodule
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_New:  
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: PackTable(Size=36)
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetVersion: 
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetVersion:  setting version 1.0 for the package
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetSettings: 
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetScript: 
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x296ED3B4, Type: Package, RefCount: 21
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_DataArray_ElementSet: Adding param: tclmodule, type: PackTable
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:  Script Name = tclmodule,
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script URI = builtin:TclModule.C
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script type = C Script
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgProvide:  name(tclmodule) version(1.0) rootScript(auth)
    Jun 28 13:30:18.000: //-1//PACK:/ComparePkgVersions:  v1(1.0) v2(1.0)
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgRequire:  name(media) version() exact(0) rootScript(auth)
    Jun 28 13:30:18.000: //-1//PACK:/find_global_package_entry:  pkgName(media) exact(0)
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgRequire:  Linking package media
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_New:  
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: PackTable(Size=36)
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetVersion: 
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetVersion:  setting version 1.0 for the package
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetSettings: 
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetScript: 
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x296ED4C4, Type: Package, RefCount: 53
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_DataArray_ElementSet: Adding param: media, type: PackTable
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:  Script Name = media,
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script URI = builtin:package_media.C
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script type = C Script
    Jun 28 13:30:18.000: //-1//PACK:/CMeth_MediaPkg_Main: 
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgProvide:  name(media) version(1.0) rootScript(auth)
    Jun 28 13:30:18.000: //-1//PACK:/ComparePkgVersions:  v1(1.0) v2(1.0)
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgRequire:  name(session_xwork) version() exact(0) rootScript(auth)
    Jun 28 13:30:18.000: //-1//PACK:/find_global_package_entry:  pkgName(session_xwork) exact(0)
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgRequire:  Linking package session_xwork
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_New:  
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: PackTable(Size=36)
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetVersion: 
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetVersion:  setting version 1.0 for the package
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetSettings: 
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetScript: 
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x296DF42C, Type: Package, RefCount: 49
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_DataArray_ElementSet: Adding param: session_xwork, type: PackTable
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:  Script Name = session_xwork,
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script URI = builtin:Session_XWork.C
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script type = C Script
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgProvide:  name(session_xwork) version(1.0) rootScript(auth)
    Jun 28 13:30:18.000: //-1//PACK:/ComparePkgVersions:  v1(1.0) v2(1.0)
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgRequire:  name(digitcollect) version() exact(0) rootScript(auth)
    Jun 28 13:30:18.000: //-1//PACK:/find_global_package_entry:  pkgName(digitcollect) exact(0)
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgRequire:  Linking package digitcollect
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_New:  
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: PackTable(Size=36)
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetVersion: 
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetVersion:  setting version 1.0 for the package
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetSettings: 
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetScript: 
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x296DEBAC, Type: Package, RefCount: 50
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_DataArray_ElementSet: Adding param: digitcollect, type: PackTable
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:  Script Name = digitcollect,
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script URI = builtinigitCollect.C
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script type = C Script
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgProvide:  name(digitcollect) version(1.0) rootScript(auth)
    Jun 28 13:30:18.000: //-1//PACK:/ComparePkgVersions:  v1(1.0) v2(1.0)
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgRequire:  name(callsetup) version() exact(0) rootScript(auth)
    Jun 28 13:30:18.000: //-1//PACK:/find_global_package_entry:  pkgName(callsetup) exact(0)
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgRequire:  Linking package callsetup
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_New:  
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: PackTable(Size=36)
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetVersion: 
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetVersion:  setting version 1.0 for the package
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetSettings: 
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetScript: 
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x296DF0FC, Type: Package, RefCount: 55
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_DataArray_ElementSet: Adding param: callsetup, type: PackTable
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:  Script Name = callsetup,
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script URI = builtin:CallSetup.C
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script type = C Script
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgProvide:  name(callsetup) version(1.0) rootScript(auth)
    Jun 28 13:30:18.000: //-1//PACK:/ComparePkgVersions:  v1(1.0) v2(1.0)
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgRequire:  name(preempt) version(1.0) exact(0) rootScript(auth)
    Jun 28 13:30:18.000: //-1//PACK:/find_global_package_entry:  pkgName(preempt) exact(0)
    Jun 28 13:30:18.000: //-1//PACK:/find_global_package_entry:  pkgVersion(1.0)
    Jun 28 13:30:18.000: //-1//PACK:/ComparePkgVersions:  v1(1.0) v2(1.0)
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgRequire:  Linking package preempt
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_New:  
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: PackTable(Size=36)
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetVersion: 
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetVersion:  setting version 1.0 for the package
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetSettings: 
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetScript: 
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x296DEFEC, Type: Package, RefCount: 56
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_DataArray_ElementSet: Adding param: preempt, type: PackTable
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:  Script Name = preempt,
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script URI = builtinreempt.C
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script type = C Script
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgProvide:  name(preempt) version(1.0) rootScript(auth)
    Jun 28 13:30:18.000: //-1//PACK:/ComparePkgVersions:  v1(1.0) v2(1.0)
    Jun 28 13:30:18.000: //-1//PACK:/ComparePkgVersions:  v1(1.0) v2(1.0)
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgRequire:  name(Retrieval) version() exact(0) rootScript(auth)
    Jun 28 13:30:18.000: //-1//PACK:/find_global_package_entry:  pkgName(Retrieval) exact(0)
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgRequire:  Linking package Retrieval
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_New:  
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: PackTable(Size=36)
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetVersion: 
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetVersion:  setting version NULL for the package
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetSettings: 
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetScript: 
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x296DF20C, Type: Package, RefCount: 50
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_DataArray_ElementSet: Adding param: Retrieval, type: PackTable
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:  Script Name = Retrieval,
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script URI = builtin:Retrieval.C
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script type = C Script
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgProvide:  name(Retrieval) version(NULL) rootScript(auth)
    Jun 28 13:30:18.000: //-1//PACK:/ComparePkgVersions:  v1(NULL) v2(NULL)
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgRequire:  name(session_xwork) version(1.0) exact(0) rootScript(auth)
    Jun 28 13:30:18.000: //-1//PACK:/ComparePkgVersions:  v1(1.0) v2(1.0)
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgRequire:  name(media) version(1.0) exact(0) rootScript(auth)
    Jun 28 13:30:18.000: //-1//PACK:/ComparePkgVersions:  v1(1.0) v2(1.0)
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgRequire:  name(consult) version() exact(0) rootScript(auth)
    Jun 28 13:30:18.000: //-1//PACK:/find_global_package_entry:  pkgName(consult) exact(0)
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgRequire:  Linking package consult
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_New:  
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: PackTable(Size=36)
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetVersion: 
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetVersion:  setting version 1.0 for the package
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetSettings: 
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetScript: 
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x296DEDCC, Type: Package, RefCount: 50
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_DataArray_ElementSet: Adding param: consult, type: PackTable
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:  Script Name = consult,
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script URI = builtin:Consult.C
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script type = C Script
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgProvide:  name(consult) version(1.0) rootScript(auth)
    Jun 28 13:30:18.000: //-1//PACK:/ComparePkgVersions:  v1(1.0) v2(1.0)
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgRequire:  name(consultresp) version() exact(0) rootScript(auth)
    Jun 28 13:30:18.000: //-1//PACK:/find_global_package_entry:  pkgName(consultresp) exact(0)
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgRequire:  Linking package consultresp
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_New:  
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: PackTable(Size=36)
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetVersion: 
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetVersion:  setting version 1.0 for the package
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetSettings: 
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_PackTable_SetScript: 
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x296DEEDC, Type: Package, RefCount: 50
    Jun 28 13:30:18.000: //-1//AFW_:/AFW_DataArray_ElementSet: Adding param: consultresp, type: PackTable
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:  Script Name = consultresp,
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script URI = builtin:ConsultResp.C
    Jun 28 13:30:18.000: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script type = C Script
    Jun 28 13:30:18.000: //-1//PACK:EE31D29988000:/PkgProvide:  name(consultresp) version(1.0) rootScript(auth)
    Jun 28 13:30:18.004: //-1//PACK:/ComparePkgVersions:  v1(1.0) v2(1.0)
    Jun 28 13:30:18.004: //-1//PACK:EE31D29988000:/PkgRequire:  name(appcommon) version() exact(0) rootScript(auth)
    Jun 28 13:30:18.004: //-1//PACK:/find_global_package_entry:  pkgName(appcommon) exact(0)
    Jun 28 13:30:18.004: //-1//PACK:EE31D29988000:/PkgRequire:  Linking package appcommon
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_PackTable_New:  
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: PackTable(Size=36)
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_PackTable_SetVersion: 
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_PackTable_SetVersion:  setting version 1.0 for the package
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_PackTable_SetSettings: 
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_PackTable_SetScript: 
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x296DEA9C, Type: Package, RefCount: 52
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataArray_ElementSet: Adding param: appcommon, type: PackTable
    Jun 28 13:30:18.004: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:  Script Name = appcommon,
    Jun 28 13:30:18.004: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script URI = builtin:AppCommon.C
    Jun 28 13:30:18.004: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script type = C Script
    Jun 28 13:30:18.004: //-1//PACK:EE31D29988000:/PkgProvide:  name(appcommon) version(1.0) rootScript(auth)
    Jun 28 13:30:18.004: //-1//PACK:/ComparePkgVersions:  v1(1.0) v2(1.0)
    Jun 28 13:30:18.004: //-1//PACK:EE31D29988000:/ParamRead:  Reading param security from appcommon
    Jun 28 13:30:18.004: //-1//PACK:/ParamRead:  Reading parameter security for a script appcommon,
    Jun 28 13:30:18.004: //-1//PACK:/ParamRead:     appRegParams=0x312ADF8C dpParamArray=0x0 pMainParamArray=0x31CE4834
    Jun 28 13:30:18.004: //-1//PACK:/ParamRead:  service level: script appcommon,
    Jun 28 13:30:18.004: //-1//PACK:/ParamRead:     pMainParamArray=0x31CE4834 pMainGroupList=0x0
    Jun 28 13:30:18.004: //-1//PACK:/ParamRead_ElementGetWithGroup:  Looking for param appcommon.security
    Jun 28 13:30:18.004: //-1//PACK:/ParamRead_ElementGetWithGroup:  Param appcommon.security was not found in this container
    Jun 28 13:30:18.004: //-1//PACK:/ParamRead:  Parameter for the script: appcommon has been read: security
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataString_Get: 
    Jun 28 13:30:18.004: //-1//ACPK:EE31D29988000:/AppCommon_SetSecurity: security = undefined
    Jun 28 13:30:18.004: //-1//PACK:EE31D29988000:/ParamRead:  Reading param event-log from appcommon
    Jun 28 13:30:18.004: //-1//PACK:/ParamRead:  Reading parameter event-log for a script appcommon,
    Jun 28 13:30:18.004: //-1//PACK:/ParamRead:     appRegParams=0x312ADF8C dpParamArray=0x0 pMainParamArray=0x31CE4834
    Jun 28 13:30:18.004: //-1//PACK:/ParamRead:  service level: script appcommon,
    Jun 28 13:30:18.004: //-1//PACK:/ParamRead:     pMainParamArray=0x31CE4834 pMainGroupList=0x0
    Jun 28 13:30:18.004: //-1//PACK:/ParamRead_ElementGetWithGroup:  Looking for param appcommon.event-log
    Jun 28 13:30:18.004: //-1//PACK:/ParamRead_ElementGetWithGroup:  Param appcommon.event-log was not found in this container
    Jun 28 13:30:18.004: //-1//PACK:/ParamRead:  Parameter for the script: appcommon has been read: event-log
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataString_Get: 
    Jun 28 13:30:18.004: //-1//ACPK:EE31D29988000:/AppCommon_SetEventLog: event-log = unconfigured
    Jun 28 13:30:18.004: //-1//PACK:EE31D29988000:/PkgRequire:  name(callfeature) version(1.0) exact(0) rootScript(auth)
    Jun 28 13:30:18.004: //-1//PACK:/find_global_package_entry:  pkgName(callfeature) exact(0)
    Jun 28 13:30:18.004: //-1//PACK:/find_global_package_entry:  pkgVersion(1.0)
    Jun 28 13:30:18.004: //-1//PACK:/ComparePkgVersions:  v1(1.0) v2(1.0)
    Jun 28 13:30:18.004: //-1//PACK:EE31D29988000:/PkgRequire:  Linking package callfeature
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_PackTable_New:  
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: PackTable(Size=36)
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_PackTable_SetVersion: 
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_PackTable_SetVersion:  setting version 1.0 for the package
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_PackTable_SetSettings: 
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_PackTable_SetScript: 
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x296DECBC, Type: Package, RefCount: 52
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataArray_ElementSet: Adding param: callfeature, type: PackTable
    Jun 28 13:30:18.004: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:  Script Name = callfeature,
    Jun 28 13:30:18.004: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script URI = builtin:CallFeature.C
    Jun 28 13:30:18.004: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script type = C Script
    Jun 28 13:30:18.004: //-1//PACK:EE31D29988000:/PkgProvide:  name(callfeature) version(1.0) rootScript(auth)
    Jun 28 13:30:18.004: //-1//PACK:/ComparePkgVersions:  v1(1.0) v2(1.0)
    Jun 28 13:30:18.004: //-1//PACK:/ComparePkgVersions:  v1(1.0) v2(1.0)
    Jun 28 13:30:18.004: //-1//PACK:EE31D29988000:/PkgRequire:  name(english) version(1.0) exact(0) rootScript(auth)
    Jun 28 13:30:18.004: //-1//PACK:/find_global_package_entry:  pkgName(english) exact(0)
    Jun 28 13:30:18.004: //-1//PACK:/find_global_package_entry:  pkgVersion(1.0)
    Jun 28 13:30:18.004: //-1//PACK:/ComparePkgVersions:  v1(1.0) v2(1.0)
    Jun 28 13:30:18.004: //-1//PACK:EE31D29988000:/PkgRequire:  Linking package english
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_PackTable_New:  
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: PackTable(Size=36)
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_PackTable_SetVersion: 
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_PackTable_SetVersion:  setting version 1.0 for the package
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_PackTable_SetSettings: 
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_PackTable_SetScript: 
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x296ED5D4, Type: Package, RefCount: 50
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataArray_ElementSet: Adding param: english, type: PackTable
    Jun 28 13:30:18.004: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:  Script Name = english,
    Jun 28 13:30:18.004: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script URI = builtin:package_english.C
    Jun 28 13:30:18.004: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script type = C Script
    Jun 28 13:30:18.004: //-1//PACK:EE31D29988000:/PkgProvide:  name(english) version(1.0) rootScript(auth)
    Jun 28 13:30:18.004: //-1//PACK:/ComparePkgVersions:  v1(1.0) v2(1.0)
    Jun 28 13:30:18.004: //-1//PACK:EE31D29988000:/PkgRequire:  name(media) version() exact(0) rootScript(auth)
    Jun 28 13:30:18.004: //-1//PACK:EE31D29988000:/ParamRead:  Reading param index from english
    Jun 28 13:30:18.004: //-1//PACK:/ParamRead:  Reading parameter index for a script english,
    Jun 28 13:30:18.004: //-1//PACK:/ParamRead:     appRegParams=0x296EE3C0 dpParamArray=0x0 pMainParamArray=0x31CE4834
    Jun 28 13:30:18.004: //-1//PACK:/ParamRead:  service level: script english,
    Jun 28 13:30:18.004: //-1//PACK:/ParamRead:     pMainParamArray=0x31CE4834 pMainGroupList=0x0
    Jun 28 13:30:18.004: //-1//PACK:/ParamRead_ElementGetWithGroup:  Looking for param english.index
    Jun 28 13:30:18.004: //-1//PACK:/ParamRead:  Parameter for the script: english has been read: index
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataString_Get: 
    Jun 28 13:30:18.004: //-1//PACK:/Lang_ReportConfig:  index=1
    Jun 28 13:30:18.004: //-1//PACK:EE31D29988000:/ParamRead:  Reading param location from english
    Jun 28 13:30:18.004: //-1//PACK:/ParamRead:  Reading parameter location for a script english,
    Jun 28 13:30:18.004: //-1//PACK:/ParamRead:     appRegParams=0x296EE3C0 dpParamArray=0x0 pMainParamArray=0x31CE4834
    Jun 28 13:30:18.004: //-1//PACK:/ParamRead:  service level: script english,
    Jun 28 13:30:18.004: //-1//PACK:/ParamRead:     pMainParamArray=0x31CE4834 pMainGroupList=0x0
    Jun 28 13:30:18.004: //-1//PACK:/ParamRead_ElementGetWithGroup:  Looking for param english.location
    Jun 28 13:30:18.004: //-1//PACK:/ParamRead:  Parameter for the script: english has been read: location
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataString_Get: 
    Jun 28 13:30:18.004: //-1//PACK:/Lang_ReportConfig:  location=flash:
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_ExecEnv_CallProc: Media::Register_Language
    Jun 28 13:30:18.004: //-1//PACK:/CMeth_Register_Language: 
    Jun 28 13:30:18.004: //-1//PACK:/CMeth_Register_Language: Register namespace english index 1 language en,
    Jun 28 13:30:18.004: //-1//PACK:/CMeth_Register_Language:    prefix en location flash:
    Jun 28 13:30:18.004: //-1//PACK:/CreateLanguageElement:  Create language with namespace english, index 1, language code en
    Jun 28 13:30:18.004: //-1//PACK:/CreateLanguageElement:     prefix en, location flash:
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataList_New: 
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataList(Size=40)
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataString_New: 
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataString(Size=20)
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataList_Enqueue:  Trying to add element to a list
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataList_GetWrapper:  Looking for list element 0x2A658F40
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataList_Enqueue:  Adding element:
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataString_New: 
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataString(Size=20)
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataList_Enqueue:  Trying to add element to a list
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataList_GetWrapper:  Looking for list element 0x2A644CF8
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataList_GetWrapper:    element 0x30078F74 containing 0x2A658F40, Prev = 0x0
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataList_Enqueue:  Adding element:
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataString_New: 
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataString(Size=20)
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataList_Enqueue:  Trying to add element to a list
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataList_Enqueue:  Adding element:
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataString_New: 
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataString(Size=20)
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataList_Enqueue:  Trying to add element to a list
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataList_Enqueue:  Adding element:
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataString_New: 
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataString(Size=20)
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataList_Enqueue:  Trying to add element to a list
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataList_GetWrapper:  Looking for list element 0x2A658E64
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataList_GetWrapper:    element 0x30078F74 containing 0x2A658F40, Prev = 0x0
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataList_GetWrapper:    element 0x3005071C containing 0x2A644CF8, Prev = 0x30078F74
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataList_GetWrapper:    element 0x29E76C60 containing 0x2A644CE4, Prev = 0x3005071C
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataList_GetWrapper:    element 0x2A350F84 containing 0x30054B90, Prev = 0x29E76C60
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataList_Enqueue:  Adding element:
    Jun 28 13:30:18.004: //-1//PACK:/AddLanguageElementToLangTbl:  Adding the language en to the language table
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataArray_ElementSetNameSpace: Adding param space media, name en, entryKey en.media, type DataList
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataArray_ElementSet: Adding param: en.media, type: DataList
    Jun 28 13:30:18.004: //-1//PACK:/Media_GetFirstLanguage: 
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataList_GetFirst: Elem = 0x30078F74, with Instance = 0x2A658F40
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataList_GetNext: Elem = 0x3005071C, with Instance = 0x2A644CF8, Prev = 0x30078F74
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataString_Get: 
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataList_GetFirst: Elem = 0x30078F74, with Instance = 0x2A658F40
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataList_GetNext: Elem = 0x3005071C, with Instance = 0x2A644CF8, Prev = 0x30078F74
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataList_GetNext: Elem = 0x29E76C60, with Instance = 0x2A644CE4, Prev = 0x3005071C
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataString_Get: 
    Jun 28 13:30:18.004: //-1//PACK:/CMeth_Register_Language:  Setting en as the current language
    Jun 28 13:30:18.004: //-1//PACK:/Media_Cur_Language_SetByLangCode:  Attempting to set en as the current language
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataString_New: 
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataString(Size=20)
    Jun 28 13:30:18.004: //-1//PACK:/Media_Cur_Language_SetByLangCode:  Setting en as the current language
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataArray_ElementSetNameSpace: Adding param space media, name Curent_Language, entryKey Curent_Language.media, type DataString
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_DataArray_ElementSet: Adding param: Curent_Language.media, type: DataString
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x2A658EF0, Type: DataString, RefCount: 2
    Jun 28 13:30:18.004: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x2A658EF0, Type: DataString, RefCount: 1
    Jun 28 13:30:18.004: //-1//PACK:/ComparePkgVersions:  v1(1.0) v2(1.0)
    Jun 28 13:30:18.004: //-1//PACK:EE31D29988000:/PkgRequire:  name(media) version(1.0) exact(0) rootScript(auth)
    Jun 28 13:30:18.004: //-1//PACK:/ComparePkgVersions:  v1(1.0) v2(1.0)
    Jun 28 13:30:18.008: //-1//PACK:EE31D29988000:/PkgRequire:  name(medianeg) version(1.0) exact(0) rootScript(auth)
    Jun 28 13:30:18.008: //-1//PACK:/find_global_package_entry:  pkgName(medianeg) exact(0)
    Jun 28 13:30:18.008: //-1//PACK:/find_global_package_entry:  pkgVersion(1.0)
    Jun 28 13:30:18.008: //-1//PACK:/ComparePkgVersions:  v1(1.0) v2(1.0)
    Jun 28 13:30:18.008: //-1//PACK:EE31D29988000:/PkgRequire:  Linking package medianeg
    Jun 28 13:30:18.008: //-1//AFW_:/AFW_PackTable_New:  
    Jun 28 13:30:18.008: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: PackTable(Size=36)
    Jun 28 13:30:18.008: //-1//AFW_:/AFW_PackTable_SetVersion: 
    Jun 28 13:30:18.008: //-1//AFW_:/AFW_PackTable_SetVersion:  setting version 1.0 for the package
    Jun 28 13:30:18.008: //-1//AFW_:/AFW_PackTable_SetSettings: 
    Jun 28 13:30:18.008: //-1//AFW_:/AFW_PackTable_SetScript: 
    Jun 28 13:30:18.008: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x296DF31C, Type: Package, RefCount: 50
    Jun 28 13:30:18.008: //-1//AFW_:/AFW_DataArray_ElementSet: Adding param: medianeg, type: PackTable
    Jun 28 13:30:18.008: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:  Script Name = medianeg,
    Jun 28 13:30:18.008: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script URI = builtin:MediaNeg.C
    Jun 28 13:30:18.008: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script type = C Script
    Jun 28 13:30:18.008: //-1//PACK:EE31D29988000:/PkgProvide:  name(medianeg) version(1.0) rootScript(auth)
    Jun 28 13:30:18.008: //-1//PACK:/ComparePkgVersions:  v1(1.0) v2(1.0)
    Jun 28 13:30:18.008: //-1//PACK:/ComparePkgVersions:  v1(1.0) v2(1.0)
    Jun 28 13:30:18.008: //-1//PACK:EE31D29988000:/PkgRequire:  name(callsnr) version(1.0) exact(0) rootScript(auth)
    Jun 28 13:30:18.008: //-1//PACK:/find_global_package_entry:  pkgName(callsnr) exact(0)
    Jun 28 13:30:18.008: //-1//PACK:/find_global_package_entry:  pkgVersion(1.0)
    Jun 28 13:30:18.008: //-1//PACK:/ComparePkgVersions:  v1(1.0) v2(1.0)
    Jun 28 13:30:18.008: //-1//PACK:EE31D29988000:/PkgRequire:  Linking package callsnr
    Jun 28 13:30:18.008: //-1//AFW_:/AFW_PackTable_New:  
    Jun 28 13:30:18.008: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: PackTable(Size=36)
    Jun 28 13:30:18.008: //-1//AFW_:/AFW_PackTable_SetVersion: 
    Jun 28 13:30:18.008: //-1//AFW_:/AFW_PackTable_SetVersion:  setting version 1.0 for the package
    Jun 28 13:30:18.008: //-1//AFW_:/AFW_PackTable_SetSettings: 
    Jun 28 13:30:18.008: //-1//AFW_:/AFW_PackTable_SetScript: 
    Jun 28 13:30:18.008: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x296EDD44, Type: Package, RefCount: 35
    Jun 28 13:30:18.008: //-1//AFW_:/AFW_DataArray_ElementSet: Adding param: callsnr, type: PackTable
    Jun 28 13:30:18.008: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:  Script Name = callsnr,
    Jun 28 13:30:18.008: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script URI = builtin:CallSnr.C
    Jun 28 13:30:18.008: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Link:     Script type = C Script
    Jun 28 13:30:18.008: //-1//PACK:EE31D29988000:/PkgProvide:  name(callsnr) version(1.0) rootScript(auth)

    Subject: RE: authentication problem
    Replied by: Anusha Kannappan on 28-06-2011 06:50:59 AM
    Hi Wesley,

    Could you please share us the logs enabling the following debugs and if possible do share us your script as well?

    deb voip application all
    deb voip aaa

    Thanks,
    Anusha

    Subject: RE: authentication problem
    Replied by: Anusha Kannappan on 29-06-2011 05:25:13 AM
    Hi Wesley,

    The logs provided by you are not complete. Have you mapped your script to any of the dial-peers or not? We don't see any traces of the script being loaded. Before collecting the logs configure the following cli and clear the logs

    !
    logging buffered 100000000

    Map your script to the dial-peer and make a call to invoke the particular script and send us the logs for further analysis.

    Thanks,
    Anusha

    Subject: RE: authentication problem
    Replied by: WESLEY PHILLIPS on 29-06-2011 10:44:09 AM
    For some reason, when I do the "debug voip app all" command, all the application debugs show up in  the "show debug" command, but some of the debugs do not go to the log. Here are some selective debugs:

    debug voip app tcl
    debug voip app script
    debug voip app error

    and here is the output from a single call:

    Jun 24 16:08:59.951: //-1//AFW_:EE31D2A0C8000:/Tcl_Link: Linking script auth
    Jun 24 16:08:59.951: //-1//TCL :EE31D2A0C8000:/tcl_RequiredVersionObjCmd: Script requires version 2.0. So 2.1 is OK
    Jun 24 16:08:59.951: //-1//TCL :EE31D2A0C8000:/tcl_InfotagObjCmd:  infotag get cfg_avpair_exists retry-count
    Jun 24 16:08:59.951: //-1//TCL :EE31D2A0C8000:/tcl_InfotagGetObjCmd: infotag get cfg_avpair_exists retry-count
    Jun 24 16:08:59.951: //-1//AFW_:EE31D2A0C8000:/vtr_cf_avpair_exists: argc 3 argindex 2
    Jun 24 16:08:59.951: //-1//TCL :EE31D2A0C8000:/tcl_InfotagObjCmd:  infotag get cfg_avpair retry-count
    Jun 24 16:08:59.951: //-1//TCL :EE31D2A0C8000:/tcl_InfotagGetObjCmd: infotag get cfg_avpair retry-count
    Jun 24 16:08:59.951: //-1//AFW_:EE31D2A0C8000:/vtr_cf_avpair: argc 3 argindex 2
    Jun 24 16:08:59.951: //-1//PACK:EE31D2A0C8000:/tcl_ParamReadObjCmd:  retry-count
    Jun 24 16:08:59.951: //-1//TCL :EE31D2A0C8000:/tcl_FSMObjCmd:  fsm define fsm CALL_INIT
    Jun 24 16:08:59.951: //-1//TCL :EE31D2A0C8000:/tcl_FSMDefineObjCmd: State Machine: Array fsm: Start State: CALL_INIT
    Jun 24 16:08:59.951: //-1//TCL :EE31D2A0C8000:/tcl_FSMDefineObjCmd: FSM Data structure
    Jun 24 16:08:59.951: (INSERTBEEP(2), ev_create_done(36)--(act_ConnectedAgain)-->(CALLACTIVE(3))
    Jun 24 16:08:59.951: (CALLDISCONNECT(4), ev_media_done(162)--(act_Cleanup)-->(samestate(5))
    Jun 24 16:08:59.951: (CALLACTIVE(3), ev_disconnected(18)--(act_Cleanup)-->(CALLDISCONNECT(4))
    Jun 24 16:08:59.951: (LASTWARN(6), ev_destroy_done(37)--(act_LastWarn)-->(CALLDISCONNECT(4))
    Jun 24 16:08:59.951: (GETACCOUNT(7), ev_collectdigits_done(210)--(act_PromptCollect_acct)-->(GETPASSWORD(8))
    Jun 24 16:08:59.951: (CALLDISCONNECT(4), ev_disconnect_done(19)--(act_Cleanup)-->(samestate(5))
    Jun 24 16:08:59.951: (CALLDISCONNECT(4), ev_leg_timer(1)--(act_Cleanup)-->(samestate(5))
    Jun 24 16:08:59.951: (INSERTBEEP(2), ev_media_done(162)--(act_Beeped)-->(samestate(5))
    Jun 24 16:08:59.951: (PLACECALL(9), ev_setup_done(201)--(act_CallSetupDone)-->(CALLACTIVE(3))
    Jun 24 16:08:59.951: (CALLACTIVE(3), ev_leg_timer(1)--(act_Timer)-->(INSERTBEEP(2))
    Jun 24 16:08:59.951: (GETPASSWORD(8), ev_collectdigits_done(210)--(act_PromptCollect_pass)-->(AUTHENTICATE(10))
    Jun 24 16:08:59.951: (any_state(0), ev_disconnected(18)--(act_Cleanup)-->(samestate(5))
    Jun 24 16:08:59.955: (AUTHENTICATE(10), ev_authenticate_done(174)--(act_Authenticated)-->(GETDEST(11))
    Jun 24 16:08:59.955: (GETDEST(11), ev_collectdigits_done(210)--(act_PromptCollect_dest)-->(PLACECALL(9))
    Jun 24 16:08:59.955: (INSERTBEEP(2), ev_destroy_done(37)--(act_Destroy)-->(samestate(5))
    Jun 24 16:08:59.955: (CALL_INIT(1), ev_setup_indication(31)--(act_Setup)-->(AUTHENTICATE(10))
    Jun 24 16:08:59.955: FSM start state CALL_INIT(1)
    Jun 24 16:08:59.955: //-1//AFW_:EE31D2A0C8000:/Tcl_Link: Script auth succesfully linked.
    Jun 24 16:08:59.955: //4074//TCL :/tcl_LegObjCmd:  leg setupack leg_incoming
    Jun 24 16:08:59.955: //4074//TCL :/tcl_LegSetupAckObjCmd: setupack leg_incoming
    Jun 24 16:08:59.955: //4074//AFW_:/vtd_lg_incoming: argc 2
    Jun 24 16:08:59.955: //4074//AFW_:/vtd_lg_incoming: Legs [4074 ]
    Jun 24 16:08:59.955: //4074//Tcl :/tcl_parseCallID_vartagObj: VARTAG Translation Leg Count=1
    Jun 24 16:08:59.955: //4074//TCL :/tcl_LegObjCmd:  leg proceeding leg_incoming
    Jun 24 16:08:59.955: //4074//TCL :/tcl_LegProceedObjCmd: proceeding leg_incoming
    Jun 24 16:08:59.955: //4074//AFW_:/vtd_lg_incoming: argc 2
    Jun 24 16:08:59.955: //4074//AFW_:/vtd_lg_incoming: Legs [4074 ]
    Jun 24 16:08:59.955: //4074//Tcl :/tcl_parseCallID_vartagObj: VARTAG Translation Leg Count=1
    Jun 24 16:08:59.955: //4074//TCL :/tcl_LegObjCmd:  leg connect leg_incoming
    Jun 24 16:08:59.955: //4074//TCL :/tcl_LegConnectObjCmd: connect leg_incoming
    Jun 24 16:08:59.955: //4074//AFW_:/vtd_lg_incoming: argc 2
    Jun 24 16:08:59.955: //4074//AFW_:/vtd_lg_incoming: Legs [4074 ]
    Jun 24 16:08:59.955: //4074//Tcl :/tcl_parseCallID_vartagObj: VARTAG Translation Leg Count=1
    Jun 24 16:08:59.955: //4074//TCL :/tcl_InfotagObjCmd:  infotag get leg_ani
    Jun 24 16:08:59.955: //4074//TCL :/tcl_InfotagGetObjCmd: infotag get leg_ani
    Jun 24 16:08:59.955: //4074//AFW_:/vtr_lg_ani: argc 2 argindex 2
    Jun 24 16:08:59.955: //4074//TCL :/tcl_InfotagObjCmd:  infotag get leg_dnis
    Jun 24 16:08:59.955: //4074//TCL :/tcl_InfotagGetObjCmd: infotag get leg_dnis
    Jun 24 16:08:59.955: //4074//AFW_:/vtr_lg_dnis: argc 2 argindex 2
    Jun 24 16:08:59.955: //4074//TCL :/tcl_AAAObjCmd:  aaa authenticate 7134224200 7134221000
    Jun 24 16:08:59.955: //4074//TCL :/tcl_AuthenticateObjCmd:  authenticate 7134224200 7134221000
    Jun 24 16:08:59.955: //4074//TCL :/tcl_AuthenticateObjCmd: account=7134224200, password=7134221000, methodList=, av-send=
    Jun 24 16:08:59.955: //4074//TCL :/tcl_AuthenticateObjCmd: Start authenticate failed
    Jun 24 16:08:59.955: //4074//TCL :/tcl_InfotagObjCmd:  infotag get evt_status
    Jun 24 16:08:59.955: //4074//TCL :/tcl_InfotagGetObjCmd: infotag get evt_status
    Jun 24 16:08:59.955: //4074//AFW_:/vtr_ev_status: argc 2 argindex 2
    Jun 24 16:08:59.955: //4074//TCL :/tcl_PutsObjCmd:
    @@@@status=au_001
    Jun 24 16:08:59.955:
    Jun 24 16:08:59.955: //4074//TCL :/tcl_InfotagObjCmd:  infotag get leg_isdid
    Jun 24 16:08:59.955: //4074//TCL :/tcl_InfotagGetObjCmd: infotag get leg_isdid
    Jun 24 16:08:59.955: //4074//AFW_:/vtr_lg_incdid: argc 2 argindex 2
    Jun 24 16:08:59.955: //4074//TCL :/tcl_LegObjCmd:  leg setup 7134221000 callInfo leg_incoming
    Jun 24 16:08:59.955: //4074//AFW_:/vtd_lg_incoming: argc 4
    Jun 24 16:08:59.955: //4074//AFW_:/vtd_lg_incoming: Legs [4074 ]
    Jun 24 16:08:59.955: //4074//Tcl :/tcl_parseCallID_vartagObj: VARTAG Translation Leg Count=1
    Jun 24 16:08:59.955: //-1//AFW_:/AFW_Util_GetTgCicValue: CIC Not  found for tag(56)
    Jun 24 16:08:59.955: //4074//OSP :/Dest_Settlement_MatrixCheck: retcode=2 cid(4074) trans=0x0, provider=0 User is not authenticated and not roaming
    Jun 24 16:08:59.955: %VOICE_IEC-3-GW: C SCRIPTS: Internal Error (OSP Fail): IEC=1.1.228.11.32.0 on callID 4074 GUID=3BC7C2049DB311E081A59A670DD4F946
    Jun 24 16:08:59.955: //4074//TCL :/tcl_FSMObjCmd:  fsm setstate PLACECALL
    Jun 24 16:08:59.955: //4074//TCL :/tcl_FSMSetStateObjCmd: setstate setstate PLACECALL
    Jun 24 16:08:59.955: //4074//TCL :/tcl_InfotagObjCmd:  infotag get evt_status
    Jun 24 16:08:59.955: //4074//TCL :/tcl_InfotagGetObjCmd: infotag get evt_status
    Jun 24 16:08:59.955: //4074//AFW_:/vtr_ev_status: argc 2 argindex 2
    Jun 24 16:08:59.955: //4074//TCL :/tcl_InfotagObjCmd:  infotag get evt_status
    Jun 24 16:08:59.955: //4074//TCL :/tcl_InfotagGetObjCmd: infotag get evt_status
    Jun 24 16:08:59.955: //4074//AFW_:/vtr_ev_status: argc 2 argindex 2
    Jun 24 16:08:59.959: //4074//TCL :/tcl_PlayToneObjCmd:  playtone leg_incoming ls_003
    Jun 24 16:08:59.959: //4074//AFW_:/vtd_lg_incoming: argc 3
    Jun 24 16:08:59.959: //4074//AFW_:/vtd_lg_incoming: Legs [4074 ]
    Jun 24 16:08:59.959: //4074//Tcl :/tcl_parseCallID_vartagObj: VARTAG Translation Leg Count=1
    Jun 24 16:09:00.179: //4074//TCL :/tcl_TimerObjCmd:  timer start leg_timer 5 leg_incoming
    Jun 24 16:09:00.179: //4074//TCL :/tcl_TimerStartObjCmd: timer start leg_timer 5 leg_incoming
    Jun 24 16:09:00.179: //4074//AFW_:/vtd_lg_incoming: argc 4
    Jun 24 16:09:00.179: //4074//AFW_:/vtd_lg_incoming: Legs [4074 ]
    Jun 24 16:09:00.179: //4074//Tcl :/tcl_parseCallID_vartagObj: VARTAG Translation Leg Count=1
    Jun 24 16:09:00.179: //4074//TCL :/tcl_FSMObjCmd:  fsm setstate CALLDISCONNECT
    Jun 24 16:09:00.179: //4074//TCL :/tcl_FSMSetStateObjCmd: setstate setstate CALLDISCONNECT
    Jun 24 16:09:05.131: //4074//TCL :/tcl_CallObjCmd:  call close
    Jun 24 16:09:05.131: //4074//TCL :/tcl_CallCloseObjCmd:  close

    Subject: RE: authentication problem
    Replied by: Yaw-Ming Chen on 29-06-2011 01:36:49 PM
    Did you logging console ?

    Don't log to console and wait for a moment then collect log
    conf t
    no logging console
    exit

    clear log

    then start test

    after test

    term len 0

    sh log | red ? (pick the destination you like)

    Subject: RE: authentication problem
    Replied by: Anusha Kannappan on 30-06-2011 03:40:12 AM
    Hi Wesley,

    From the logs provided it is seen that call is getting disconnected as it has received ls_003 which infers that the call setup failed because of a lack of resources in the network and nothing to do with the authentication stuff.

    BTW have you modified your script again? Because after getting the status as au_001 it was directly doing a leg setup as per the script you had provided but in the logs it is executing the infotag get leg_isdid. Why there is discripency over here?

    @@@@status=au_001
    Jun 24 16:08:59.955:
    Jun 24 16:08:59.955: //4074//TCL :/tcl_InfotagObjCmd: infotag get leg_isdid
    Jun 24 16:08:59.955: //4074//TCL :/tcl_InfotagGetObjCmd: infotag get leg_isdid
    Jun 24 16:08:59.955: //4074//AFW_:/vtr_lg_incdid: argc 2 argindex 2
    Jun 24 16:08:59.955: //4074//TCL :/tcl_LegObjCmd: leg setup 7134221000 callInfo leg_incoming

    Thanks,
    Anusha

    Subject: RE: authentication problem
    Replied by: WESLEY PHILLIPS on 30-06-2011 09:06:16 AM
    my apologies. that was a debug from a previous attempted script. I set the logging buffer to a larger value and turned off logging monitor as suggested above. Here is the call with all the debugs originally requested:

    Jun 30 13:05:19.024: //-1//SCRI:/ScriptList_CacheCurrent:  auth
    Jun 30 13:06:10.072: //4110/CD63A95A81EC/VAAA:0/voip_start_ccapi_accounting: WARNING: gw-accounting aaa not enabled. return.
    Jun 30 13:06:10.072: //-1//SERV:/AFW_Service_CCInterface: Received Event 25 for service auth modulehandle NULL
    Jun 30 13:06:10.072: //-1//SERV:/AFW_Service_GetExecEnv: Script Name = auth
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_Process_New: auth
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: Process(Size=128)
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x30E813F4, Type: ProcManager, RefCount: 2
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x31D29988, Type: ExecEnv, RefCount: 1
    Jun 30 13:06:10.072: //-1//SERV:/AFW_Service_GetExecEnv: Using Cached ExecEnv
    Jun 30 13:06:10.072: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_SetRoot: Execenv = 0x31D29988
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: TclModule(Size=368)
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_M_TclModule_NewDup: 
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_DataArray_New: 
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataArray(Size=80)
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: FSM(Size=104)
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x300CDF88, Type: TclModule, RefCount: 0
    Jun 30 13:06:10.072: //-1//AFW_:HN1EC4C9C8:/AFW_M_TclModule_Free:  MOD[TclModule_300CDF88_0_516153608]       ( )
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x2A64CA34, Type: FSM, RefCount: 0
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_M_FSM_Free: 
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x2A618074, Type: DataArray, RefCount: 0
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_Process_Lock: pProcess(0x3144788C)=1
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x3144788C, Type: Process, RefCount: 2
    Jun 30 13:06:10.072: //-1//AFW_:LP:EE31D29988000:HN28FA8120:/AFW_M_Object_SetExecEnv: ObjCount: 1, CmdPending 0
    Jun 30 13:06:10.072: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_RestoreDataBackup: Restore DataArea from Script
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataArray(Size=80)
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_M_DataArray_NewDup:  param_name: Curent_Language, param_namespace: media
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataString(Size=20)
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_DataArray_ElementSetNameSpace: Adding param space media, name Curent_Language, entryKey Curent_Language.media, type DataString
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_DataArray_ElementSet: Adding param: Curent_Language.media, type: DataString
    Jun 30 13:06:10.072: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_RestoreDataBackup: Restore TokenTable from Script
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataArray(Size=80)
    Jun 30 13:06:10.072: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_Initiate: Execenv = 0x31D29988
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x313DD624, Type: TclModule, RefCount: 2
    Jun 30 13:06:10.072: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_SetCallCorID:
    Jun 30 13:06:10.072:  CallCorID is Mc)Z"P^Q`^Al^Zg
    TyF
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_Leg_New: 
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: Leg(Size=4872)
    Jun 30 13:06:10.072: //4110//AFW_:/AFW_M_Leg_SetExecEnv: 
    Jun 30 13:06:10.072: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_IncrPendingCmd:  PendingCmdCount: 1
    Jun 30 13:06:10.072: //-1//AFW_:LP:EE31D29988000:LG4110:/AFW_M_Object_SetExecEnv: ObjCount: 2, CmdPending 1
    Jun 30 13:06:10.072: //4110//AFW_:/AFW_Object_AddListener: adding Module TclModule as listener
    Jun 30 13:06:10.072: //4110//AFW_:/AFW_M_Leg_GetHandle: Leg handle: LEG_4110
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_DataArray_ElementSet: Adding param: LEG_4110, type: Leg
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x31C39E90, Type: Leg, RefCount: 2
    Jun 30 13:06:10.072: //-1//AFW_:EE31D29988000:/AFW_ExecEnv_AssignCall: Execenv = 0x31D29988, Leg = 4110, Peer_Tag = 10
    Jun 30 13:06:10.072: //4110//AFW_:/AFW_ExecEnv_SetCallCorID:
    Jun 30 13:06:10.072:  CallCorID is Mc)Z"P^Q`^Al^Zg
    TyF
    Jun 30 13:06:10.072: //-1//SERV:/AFW_Service_Process_Space:
    Jun 30 13:06:10.072: Process Started
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_Process_Register: ccAppInitialize(name: _ManagedAppProcess_auth)
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_Event_New: Event ID: ev_any_event
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: Event(Size=2608)
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_DataList_New: 
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataList(Size=40)
    Jun 30 13:06:10.072: //4110//AFW_:/AFW_Process_GetCcqEvent: Received
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_Process_GetCcqEvent:   Event[CC_EV_CALL_SETUP_IND(31)] {
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_Process_GetCcqEvent:     EXECENV[0x31D29988]
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_Process_GetCcqEvent:     LEG[4110][LEG_INIT(0)][Cause(0)]
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_Process_GetCcqEvent:   }
    Jun 30 13:06:10.072: //4110//SSIN:/AFW_SS_MapEvent: 
    Jun 30 13:06:10.072: //-1//SSIN:/AFW_SS_H323_MapEvent: 
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_Util_SaveRawMsg: 
    Jun 30 13:06:10.072: //4110/CD63A95A81EC/AFW_:/AFW_Leg_UpdateStats: Updating stats for ID 842 type 0
    Jun 30 13:06:10.072: //4110/CD63A95A81EC/AFW_:/incrementIncomingDialPeerCallStats: Incrementing call-stat for dial-peer [10]
    Jun 30 13:06:10.072: //4110/CD63A95A81EC/AFW_:/AFW_Object_WalkListeners: 
    Jun 30 13:06:10.072: //4110/CD63A95A81EC/AFW_:/AFW_M_Object_ShowListeners: START
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_M_Object_ShowListeners:  
    Jun 30 13:06:10.072: //4110//AFW_:/AFW_M_Module_GetHandle: Module handle: TclModule_313DD624_0_687505696MOD[TclModule_313DD624_0_687505696]  (
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_M_Object_ShowListeners:     LEG[4110][LEG_INCINIT(1)][Cause(0)]
    Jun 30 13:06:10.072: //-1//AFW_:/AFW_M_Object_ShowListeners:   )
    Jun 30 13:06:10.072: //4110/CD63A95A81EC/AFW_:/AFW_M_Object_ShowListeners: END
    Jun 30 13:06:10.072: //4110/CD63A95A81EC/AFW_:/AFW_Object_WalkListeners: Entering Module : TclModule
    Jun 30 13:06:10.072: //4110//AFW_:/AFW_ExecEnv_SetModuleScope: TclModule_313DD624_0_687505696 ---> TclModule_313DD624_0_687505696
    Jun 30 13:06:10.072: //4110//AFW_:/AFW_M_TclModule_Action: 
    Jun 30 13:06:10.072: //4110//AFW_:/AFW_TclModule_DefaultEvHandling: 
    Jun 30 13:06:10.072: //4110/CD63A95A81EC/AFW_:/AFW_Leg_CheckIncomingCallBlock: 
    Jun 30 13:06:10.072: //4110/CD63A95A81EC/AFW_:/AFW_Leg_SettlementValidateCall: target=ipv4:172.17.254.6, tokenp=0x0
    Jun 30 13:06:10.072: //4110/CD63A95A81EC/AFW_:/AFW_Leg_IncomingTranslate: 
    Jun 30 13:06:10.072: //4110//AFW_:/AFW_FSM_Drive: ACTION BEGIN: ------(CALL_INIT[1],ev_setup_indication[31])---[act_Setup]------
    Jun 30 13:06:10.072: //4110//TCL :/tcl_LegObjCmd:  leg setupack leg_incoming
    Jun 30 13:06:10.072: //4110//TCL :/tcl_LegSetupAckObjCmd: setupack leg_incoming
    Jun 30 13:06:10.072: //4110//AFW_:/vtd_lg_incoming: argc 2
    Jun 30 13:06:10.072: //4110//AFW_:/vtd_lg_incoming: Legs [4110 ]
    Jun 30 13:06:10.072: //4110//Tcl :/tcl_parseCallID_vartagObj: VARTAG Translation Leg Count=1
    Jun 30 13:06:10.072: //4110//TCL :/tcl_LegObjCmd:  leg proceeding leg_incoming
    Jun 30 13:06:10.072: //4110//TCL :/tcl_LegProceedObjCmd: proceeding leg_incoming
    Jun 30 13:06:10.072: //4110//AFW_:/vtd_lg_incoming: argc 2
    Jun 30 13:06:10.072: //4110//AFW_:/vtd_lg_incoming: Legs [4110 ]
    Jun 30 13:06:10.072: //4110//Tcl :/tcl_parseCallID_vartagObj: VARTAG Translation Leg Count=1
    Jun 30 13:06:10.076: //4110//TCL :/tcl_LegObjCmd:  leg connect leg_incoming
    Jun 30 13:06:10.076: //4110//TCL :/tcl_LegConnectObjCmd: connect leg_incoming
    Jun 30 13:06:10.076: //4110//AFW_:/vtd_lg_incoming: argc 2
    Jun 30 13:06:10.076: //4110//AFW_:/vtd_lg_incoming: Legs [4110 ]
    Jun 30 13:06:10.076: //4110//Tcl :/tcl_parseCallID_vartagObj: VARTAG Translation Leg Count=1
    Jun 30 13:06:10.076: //4110/CD63A95A81EC/AFW_:/AFW_Leg_Connect: prog_ind=0, ccRawMsgInfo_t=0x32507134, cData=0
    Jun 30 13:06:10.076: //-1//SSIN:/AFW_SS_H450_PrepareCommonInfo: Leg peer_tag=10
    Jun 30 13:06:10.076: //-1//SSIN:/AFW_SS_H450_PrepareCIInform: 
    Jun 30 13:06:10.076: //4110/CD63A95A81EC/AFW_:/AFW_Leg_UpdateStats: Updating stats for ID 842 type 1
    Jun 30 13:06:10.076: //4110//TCL :/tcl_InfotagObjCmd:  infotag get leg_ani
    Jun 30 13:06:10.076: //4110//TCL :/tcl_InfotagGetObjCmd: infotag get leg_ani
    Jun 30 13:06:10.076: //4110//AFW_:/vtr_lg_ani: argc 2 argindex 2
    Jun 30 13:06:10.076: //4110//TCL :/tcl_InfotagObjCmd:  infotag get leg_dnis
    Jun 30 13:06:10.076: //4110//TCL :/tcl_InfotagGetObjCmd: infotag get leg_dnis
    Jun 30 13:06:10.076: //4110//AFW_:/vtr_lg_dnis: argc 2 argindex 2
    Jun 30 13:06:10.076: //4110//TCL :/tcl_AAAObjCmd:  aaa authenticate 7134224200 7134221000
    Jun 30 13:06:10.076: //4110//TCL :/tcl_AuthenticateObjCmd:  authenticate 7134224200 7134221000
    Jun 30 13:06:10.076: //4110//TCL :/tcl_AuthenticateObjCmd: account=7134224200, password=7134221000, methodList=, av-send=
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_Event_New: Event ID: ev_authenticate_done
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: Event(Size=2608)
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_DataList_New: 
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataList(Size=40)
    Jun 30 13:06:10.076: //4110//AFW_:/AFW_ExecEnv_IncrPendingCmd:  PendingCmdCount: 2
    Jun 30 13:06:10.076: //-1//VAAA:0/voip_start_authentication: name:7134224200, service:ivr tcl authentication, method:
    Jun 30 13:06:10.076: //-1//VAAA:0/voip_alloc_aaa_uid: 
    Jun 30 13:06:10.076: //-1//VAAA:0/voip_start_authentication: UID=2506
    Jun 30 13:06:10.076: voip_aaa_get_method_index(0): ERROR: method "h323" not defined.
    Jun 30 13:06:10.076: //-1//VAAA:0/voip_start_authentication: No authen list
    Jun 30 13:06:10.076: //-1//VAAA:0/voip_set_release_source: src[8]

    Jun 30 13:06:10.076: //4110//TCL :/tcl_AuthenticateObjCmd: Start authenticate failed
    Jun 30 13:06:10.076: //4110//AFW_:/AFW_Event_IsOk: AppEventOk Success - timestamp MATCHED
    Jun 30 13:06:10.076: //4110//AFW_:/AFW_ExecEnv_DecrNPendingCmd:  PendingCmdCount: 1
    Jun 30 13:06:10.076: //4110//AFW_:/AFW_FSM_Drive: ACTION END: -------------(AUTHENTICATE[10])---------------
    Jun 30 13:06:10.076: //4110//AFW_:/AFW_ExecEnv_SetModuleScope: TclModule_313DD624_0_687505696 ---> TclModule_313DD624_0_687505696
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x30007040, Type: Event, RefCount: 0
    Jun 30 13:06:10.076: //4110/CD63A95A81EC/AFW_:/AFW_M_Event_Free: 
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x31D8FB40, Type: DataList, RefCount: 0
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_M_DataList_Free: 
    Jun 30 13:06:10.076: //4110//AFW_:/AFW_ExecEnv_CloseIfDone: Cmd Count: 1
    Jun 30 13:06:10.076: //4110//AFW_:/AFW_Event_IsOk: AppEventOk Success - timestamp MATCHED
    Jun 30 13:06:10.076: //4110//AFW_:/AFW_Process_GetAppQEvent: Received
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_Process_GetAppQEvent:   Event[APP_EV_AUTHENTICATE_DONE(174)] {
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_Process_GetAppQEvent:     EXECENV[0x31D29988]
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_Process_GetAppQEvent:     MOD[TclModule_313DD624_0_687505696]  (
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_Process_GetAppQEvent:       LEG[4110][LEG_INCCONNECTED(5)][Cause(0)]
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_Process_GetAppQEvent:     )
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_Process_GetAppQEvent:   }
    Jun 30 13:06:10.076: //4110//AFW_:/AFW_M_TclModule_EventPreProcess: 
    Jun 30 13:06:10.076: //4110//AFW_:/AFW_ExecEnv_SetModuleScope: NULL ---> TclModule_313DD624_0_687505696
    Jun 30 13:06:10.076: //4110//AFW_:/AFW_M_TclModule_Action: 
    Jun 30 13:06:10.076: //4110//AFW_:/AFW_TclModule_DefaultEvHandling: 
    Jun 30 13:06:10.076: //4110//AFW_:/AFW_FSM_Drive: ACTION BEGIN: ------(AUTHENTICATE[10],ev_authenticate_done[174])---[act_Authenticated]------
    Jun 30 13:06:10.076: //4110//TCL :/tcl_InfotagObjCmd:  infotag get evt_status
    Jun 30 13:06:10.076: //4110//TCL :/tcl_InfotagGetObjCmd: infotag get evt_status
    Jun 30 13:06:10.076: //4110//AFW_:/vtr_ev_status: argc 2 argindex 2
    Jun 30 13:06:10.076: //4110//TCL :/tcl_PutsObjCmd:
    @@@@status=au_001
    Jun 30 13:06:10.076:
    Jun 30 13:06:10.076: //4110//TCL :/tcl_LegObjCmd:  leg setup 7134221000 callInfo leg_incoming
    Jun 30 13:06:10.076: //4110//CSPK:/tcl_LegSetupObjCmd: leg setup 7134221000 callInfo leg_incoming
    Jun 30 13:06:10.076: //4110//AFW_:/vtd_lg_incoming: argc 4
    Jun 30 13:06:10.076: //4110//AFW_:/vtd_lg_incoming: Legs [4110 ]
    Jun 30 13:06:10.076: //4110//Tcl :/tcl_parseCallID_vartagObj: VARTAG Translation Leg Count=1
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_Util_GetTgCicValue: CIC Not  found for tag(56)
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_ExecEnv_CallProc: CallSetup::Start
    Jun 30 13:06:10.076: //4110//CSPK:/C_CallSetup_Start: ControlInfo = 0x31BB6234, callInfo = 0x31D3EEDC, destination[0]=7134221000
    Jun 30 13:06:10.076: //4110//PACK:/ParamRead:  Reading param mode from callsetup
    Jun 30 13:06:10.076: //-1//PACK:/ParamRead:  Reading parameter mode for a script callsetup,
    Jun 30 13:06:10.076: //-1//PACK:/ParamRead:     appRegParams=0x313C9104 dpParamArray=0x0 pMainParamArray=0x31CE4834
    Jun 30 13:06:10.076: //-1//PACK:/ParamRead:  service level: script callsetup,
    Jun 30 13:06:10.076: //-1//PACK:/ParamRead:     pMainParamArray=0x31CE4834 pMainGroupList=0x0
    Jun 30 13:06:10.076: //-1//PACK:/ParamRead_ElementGetWithGroup:  Looking for param callsetup.mode
    Jun 30 13:06:10.076: //-1//PACK:/ParamRead_ElementGetWithGroup:  Param callsetup.mode was not found in this container
    Jun 30 13:06:10.076: //-1//PACK:/ParamRead:  Parameter for the script: callsetup has been read: mode
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_DataString_Get: 
    Jun 30 13:06:10.076: //4110//CSPK:/C_CallSetup_Start: configured mode=rotary (1)
    Jun 30 13:06:10.076: //4110//PACK:/ParamRead:  Reading param reroutemode from callsetup
    Jun 30 13:06:10.076: //-1//PACK:/ParamRead:  Reading parameter reroutemode for a script callsetup,
    Jun 30 13:06:10.076: //-1//PACK:/ParamRead:     appRegParams=0x313C9104 dpParamArray=0x0 pMainParamArray=0x31CE4834
    Jun 30 13:06:10.076: //-1//PACK:/ParamRead:  service level: script callsetup,
    Jun 30 13:06:10.076: //-1//PACK:/ParamRead:     pMainParamArray=0x31CE4834 pMainGroupList=0x0
    Jun 30 13:06:10.076: //-1//PACK:/ParamRead_ElementGetWithGroup:  Looking for param callsetup.reroutemode
    Jun 30 13:06:10.076: //-1//PACK:/ParamRead_ElementGetWithGroup:  Param callsetup.reroutemode was not found in this container
    Jun 30 13:06:10.076: //-1//PACK:/ParamRead:  Parameter for the script: callsetup has been read: reroutemode
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_DataString_Get: 
    Jun 30 13:06:10.076: //4110//CSPK:/C_CallSetup_Start: configured reroutemode=rotary (1)
    Jun 30 13:06:10.076: //-1//Call:/AFW_CallSetup_New: 
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: CallSetup(Size=4688)
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_DataArray_New: 
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataArray(Size=80)
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_FSM_New: 
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: FSM(Size=104)
    Jun 30 13:06:10.076: //-1//AFW_:LP:EE31D29988000:HN28FA8124:/AFW_M_Object_SetExecEnv: ObjCount: 3, CmdPending 1
    Jun 30 13:06:10.076: //4110//AFW_:/AFW_ExecEnv_IncrPendingCmd:  PendingCmdCount: 2
    Jun 30 13:06:10.076: //4110//AFW_:/AFW_Object_AddListener: adding Module TclModule as listener
    Jun 30 13:06:10.076: //4110//AFW_:/AFW_M_Module_GetHandle: Module handle: CallSetup_2A696210_0_687505700
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_DataArray_ElementSet: Adding param: CallSetup_2A696210_0_687505700, type: CallSetup
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x2A696210, Type: CallSetup, RefCount: 2
    Jun 30 13:06:10.076: //4110//Call:/AFW_CallSetup_AddDest:  7134221000 index 0
    Jun 30 13:06:10.076: //4110//Call:/AFW_CallSetup_SetIntWrkLeg: 
    Jun 30 13:06:10.076: //4110/CD63A95A81EC/AFW_:/AFW_Leg_SignalPeerGet: Leg [4110]
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_ExecEnv_CallProc: Session::GetSigPeer
    Jun 30 13:06:10.076: //-1//AFW_:/C_PackageSession_GetSigPeer: 
    Jun 30 13:06:10.076: //4110/CD63A95A81EC/AFW_:/C_PackageSession_GetSigPeer: No Interworking module on Leg, no signal peer
    Jun 30 13:06:10.076: //4110//Call:/AFW_M_CallSetup_Initiate: 
    Jun 30 13:06:10.076: //4110//Call:/CS_UpdateMLPPInfo: MLPP info not available and hence not updated
    Jun 30 13:06:10.076: //4110//Call:/CallSetupInitiate: 
    Jun 30 13:06:10.076: //4110//Call:/CS_Placecall: 
    Jun 30 13:06:10.076: //4110//Call:/CS_UpdateMLPPInfo: MLPP info not available and hence not updated
    Jun 30 13:06:10.076: //-1//Dest:/AFW_Destination_New: 
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: Destination(Size=11816)
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_DataArray_New: 
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataArray(Size=80)
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_FSM_New: 
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: FSM(Size=104)
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_FSM_New: 
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: FSM(Size=104)
    Jun 30 13:06:10.076: //-1//AFW_:LP:EE31D29988000:HN28FA8124:/AFW_M_Object_SetExecEnv: ObjCount: 4, CmdPending 2
    Jun 30 13:06:10.076: //4110//AFW_:/AFW_ExecEnv_IncrPendingCmd:  PendingCmdCount: 3
    Jun 30 13:06:10.076: //4110//AFW_:/AFW_Object_AddListener: adding Module CallSetup as listener
    Jun 30 13:06:10.076: //4110//AFW_:/AFW_M_Module_GetHandle: Module handle: Destination_31C3DFF4_0_687505700
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_DataArray_ElementSet: Adding param: Destination_31C3DFF4_0_687505700, type: Destination
    Jun 30 13:06:10.076: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x31C3DFF4, Type: Destination, RefCount: 2
    Jun 30 13:06:10.076: //4110//Dest:/AFW_Destination_AddDest: 
    Jun 30 13:06:10.080: //-1//Dest:/AFW_Destination_AddDest: adding destination "7134221000"
    Jun 30 13:06:10.080: //4110//Dest:/AFW_Destination_SetIntWrkLeg: LEG[4110   ][LEG_INCCONNECTED(5)][Cause(0)]
    Jun 30 13:06:10.080: //4110//Dest:/TermInterworking: current state IW_STATE_INIT, Keep IntWrkLeg
    Jun 30 13:06:10.080: //4110//Dest:/DestSetIntWrkLeg:
    Jun 30 13:06:10.080: //4110/CD63A95A81EC/AFW_:/AFW_Object_AddListener: adding Module Destination as listener
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_DataArray_ElementSet: Adding param: LEG_4110, type: Leg
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x31C39E90, Type: Leg, RefCount: 3
    Jun 30 13:06:10.080: //4110//Dest:/AFW_M_Destination_Initiate: 
    Jun 30 13:06:10.080: //-1//VAAA:0/voip_rot_acct_supp_enabled: Rotary suppress disabled
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_Util_SaveRawMsg: 
    Jun 30 13:06:10.080: //4110//Dest:/AFW_M_Destination_Initiate: Outgoing guid : CD63A95A.A25011E0.81EC9A67.0DD4F946
    Jun 30 13:06:10.080:  Incoming_guid : 00000000.00000000.00000000.00000000
    Jun 30 13:06:10.080: //4110//Dest:/AFW_M_Destination_Initiate: Outgoing gcid : 00000000.00000000.00000000.00000000
    Jun 30 13:06:10.080:  Incoming_gcid : 00000000.00000000.00000000.00000000
    Jun 30 13:06:10.080: //4110//Dest:/DestUpdateMLPPInfo: MLPP Information not available and hence not updated
    Jun 30 13:06:10.080: //4110//Dest:/DestSetupInitiate: 
    Jun 30 13:06:10.080: //4110//Dest:/DestAddRerouteSetupInfo: 
    Jun 30 13:06:10.080: //4110//Dest:/DestAddTransferSetupInfo: 
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_Util_CopyCallDataToCallInfo: copied 7134221000

    Jun 30 13:06:10.080: //4110//PACK:/ParamRead:  Reading param after-hours-exempt from callsetup
    Jun 30 13:06:10.080: //-1//PACK:/ParamRead:  Reading parameter after-hours-exempt for a script callsetup,
    Jun 30 13:06:10.080: //-1//PACK:/ParamRead:     appRegParams=0x313C9104 dpParamArray=0x0 pMainParamArray=0x31CE4834
    Jun 30 13:06:10.080: //-1//PACK:/ParamRead:  service level: script callsetup,
    Jun 30 13:06:10.080: //-1//PACK:/ParamRead:     pMainParamArray=0x31CE4834 pMainGroupList=0x0
    Jun 30 13:06:10.080: //-1//PACK:/ParamRead_ElementGetWithGroup:  Looking for param callsetup.after-hours-exempt
    Jun 30 13:06:10.080: //-1//PACK:/ParamRead_ElementGetWithGroup:  Param callsetup.after-hours-exempt was not found in this container
    Jun 30 13:06:10.080: //-1//PACK:/ParamRead:  Parameter for the script: callsetup has been read: after-hours-exempt
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_DataBoolean_Get: 
    Jun 30 13:06:10.080: //4110//Dest:/DestMatchDialPeer: 
    Jun 30 13:06:10.080: //4110//Dest:/DestMatchDialPeer: src carrier id:, tgt carrier id:
    Jun 30 13:06:10.080: //4110//Dest:/DestQueuePeers: Matched peers:
    Jun 30 13:06:10.080: //4110//Dest:/DestPeerItemUpdatePreemptInfo: 
    Jun 30 13:06:10.080: //-1//Dest:/DestQueuePeers:  100
    Jun 30 13:06:10.080: //-1//Dest:/DestQueuePeers: , Total(1)
    Jun 30 13:06:10.080: //4110//Dest:/DestDialPeerRotary: 
    Jun 30 13:06:10.080: //4110//Dest:/DestOutboundCallUsingPeer: dest(7134221000), numexpDest(7134221000), numDestDigits(0)
    Jun 30 13:06:10.080: //4110//Dest:/DestOutboundCallUsingPeer:    prefix(), peer tag(100)
    Jun 30 13:06:10.080: //4110//Dest:/DestUpdatePreemptSetupInfo: 
    Jun 30 13:06:10.080: //4110//OSP :/Dest_Settlement_MatrixCheck: retcode=2 cid(4110) trans=0x0, provider=0 User is not authenticated and not roaming
    Jun 30 13:06:10.080: %VOICE_IEC-3-GW: C SCRIPTS: Internal Error (OSP Fail): IEC=1.1.228.11.32.0 on callID 4110 GUID=CD63A95AA25011E081EC9A670DD4F946
    Jun 30 13:06:10.080: //4110//Dest:/DestSetupInitiate:  Dial peer rotary failed
    Jun 30 13:06:10.080: //4110//Dest:/DestSetupInitiate:
    Jun 30 13:06:10.080:  : before setting failure to featvsa
    Jun 30 13:06:10.080: //-1//Dest:/DestSetFailureToFeatureVsa:
    Jun 30 13:06:10.080: Inside FailureFun. callid is 4110,fname is 0, -1
    Jun 30 13:06:10.080: //-1//Dest:/DestSetFailureToFeatureVsa:
    Jun 30 13:06:10.080:  Feature vsa is 301B6268, feature res = 1
    Jun 30 13:06:10.080: //-1//Dest:/DestSetFailureToFeatureVsa:
    Jun 30 13:06:10.080: //4110//Dest:/DestSetupInitiate:
    Jun 30 13:06:10.080:  : after setting failure to featvsa
    Jun 30 13:06:10.080: //4110//Dest:/DestResetCallInfo: 
    Jun 30 13:06:10.080: //4110//Dest:/DestComplete: peer #:100 IW State IW_STATE_INIT, OB State OB_STATE_INIT
    Jun 30 13:06:10.080: //-1//Dest:/DestStatusFromDiscCause: mapped "no route to destination (3)"(3) to DEST_NO_RESOURCE(3)
    Jun 30 13:06:10.080: //4110//Dest:/DestUpdateMLPPCause: status=3, cause=3
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_Event_New: Event ID: ev_destination_done
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: Event(Size=2608)
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_DataList_New: 
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataList(Size=40)
    Jun 30 13:06:10.080: //4110//AFW_:/AFW_Module_ReturnArgEv: 
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_DataList_New: 
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataList(Size=40)
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_DataList_Enqueue:  Trying to add element to a list
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_DataList_GetWrapper:  Looking for list element 0x31C39E90
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_DataList_Enqueue:  Adding element:
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x31C39E90, Type: Leg, RefCount: 4
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_DataList_GetFirst: Elem = 0x300EBBD0, with Instance = 0x31C39E90
    Jun 30 13:06:10.080: //4110//AFW_:/AFW_Module_ReturnArgEv: Return List (remove=TRUE){LEG[4110   ][LEG_INCCONNECTED(5)][Cause(0)]}
    Jun 30 13:06:10.080: //4110/CD63A95A81EC/AFW_:/AFW_Object_RemoveListener: 
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_DataArray_ElementDelete: param name LEG_4110
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x31C39E90, Type: Leg, RefCount: 3
    Jun 30 13:06:10.080: //4110//AFW_:/AFW_Module_UnListen:  NumObjects: 0
    Jun 30 13:06:10.080: //4110//Dest:/DestReturn: Destination Returning(ds_003 Status DEST_NO_RESOURCE)
    Jun 30 13:06:10.080: //4110//Call:/CS_Placecall: Call placed to 7134221000 index 0
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_DataString_New: 
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataString(Size=20)
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_DataArray_ElementSetNameSpace: Adding param space Session, name LastCmdHandle, entryKey LastCmdHandle.Session, type DataString
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_DataArray_ElementSet: Adding param: LastCmdHandle.Session, type: DataString
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x2A658E3C, Type: DataString, RefCount: 2
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x2A658E3C, Type: DataString, RefCount: 1
    Jun 30 13:06:10.080: //4110//TCL :/tcl_FSMObjCmd:  fsm setstate PLACECALL
    Jun 30 13:06:10.080: //4110//TCL :/tcl_FSMSetStateObjCmd: setstate setstate PLACECALL
    Jun 30 13:06:10.080: //4110//AFW_:/AFW_FSM_Drive: ACTION END: -------------(PLACECALL[9])---------------
    Jun 30 13:06:10.080: //4110//AFW_:/AFW_ExecEnv_SetModuleScope: TclModule_313DD624_0_687505696 ---> NULL
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x30007A70, Type: Event, RefCount: 0
    Jun 30 13:06:10.080: //4110//AFW_:/AFW_M_Event_Free: 
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x31D8FBB8, Type: DataList, RefCount: 0
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_M_DataList_Free: 
    Jun 30 13:06:10.080: //4110//AFW_:/AFW_ExecEnv_CloseIfDone: Cmd Count: 3
    Jun 30 13:06:10.080: //4110//AFW_:/AFW_Event_IsOk: AppEventOk Success - timestamp MATCHED
    Jun 30 13:06:10.080: //4110//AFW_:/AFW_Process_GetPriorityQEvent: Received
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_Process_GetPriorityQEvent:   Event[APP_EV_DESTINATION_DONE(203)] {
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_Process_GetPriorityQEvent:     EXECENV[0x31D29988]
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_Process_GetPriorityQEvent:     MOD[Destination_31C3DFF4_0_687505700]  (
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_Process_GetPriorityQEvent:     )
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_Process_GetPriorityQEvent:   }
    Jun 30 13:06:10.080: //4110//Dest:/AFW_M_Destination_EventPreProcess: 
    Jun 30 13:06:10.080: //4110//AFW_:/AFW_Object_WalkListeners: 
    Jun 30 13:06:10.080: //4110//AFW_:/AFW_M_Object_ShowListeners: START
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_M_Object_ShowListeners:   MOD[CallSetup_2A696210_0_687505700]  (
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_M_Object_ShowListeners:     MOD[Destination_31C3DFF4_0_687505700]  (
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_M_Object_ShowListeners:     )
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_M_Object_ShowListeners:   )
    Jun 30 13:06:10.080: //4110//AFW_:/AFW_M_Object_ShowListeners: END
    Jun 30 13:06:10.080: //4110//AFW_:/AFW_Object_WalkListeners: Entering Module : CallSetup
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_DataList_GetFirst: Elem = 0x300EBBD0, with Instance = 0x31C39E90
    Jun 30 13:06:10.080: //4110/CD63A95A81EC/AFW_:/AFW_Object_AddListener: adding Module CallSetup as listener
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_DataArray_ElementSet: Adding param: LEG_4110, type: Leg
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x31C39E90, Type: Leg, RefCount: 4
    Jun 30 13:06:10.080: //4110//AFW_:/AFW_Object_RemoveListener: 
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_DataArray_ElementDelete: param name Destination_31C3DFF4_0_687505700
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x31C3DFF4, Type: Destination, RefCount: 1
    Jun 30 13:06:10.080: //4110//AFW_:/AFW_Module_UnListen:  NumObjects: 1
    Jun 30 13:06:10.080: //4110//AFW_:/AFW_ExecEnv_SetModuleScope: NULL ---> CallSetup_2A696210_0_687505700
    Jun 30 13:06:10.080: //4110//Call:/AFW_M_CallSetup_Action: 
    Jun 30 13:06:10.080: //4110//AFW_:/AFW_FSM_Drive: ACTION BEGIN: ------(S_PLACECALL[2],ev_destination_done[203])---[C_Action]------
    Jun 30 13:06:10.080: //4110//Call:/CS_Placecall_DestDone: 
    Jun 30 13:06:10.080: //4110//AFW_:/AFW_FSM_Drive: ACTION END: -------------(S_DONE[13])---------------
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_Event_New: Event ID: ev_setup_done
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: Event(Size=2608)
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_DataList_New: 
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataList(Size=40)
    Jun 30 13:06:10.080: //4110//AFW_:/AFW_Module_ReturnArgEv: 
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_DataList_New: 
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataList(Size=40)
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_DataList_Enqueue:  Trying to add element to a list
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_DataList_GetWrapper:  Looking for list element 0x31C39E90
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_DataList_Enqueue:  Adding element:
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x31C39E90, Type: Leg, RefCount: 5
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_DataList_GetFirst: Elem = 0x3006A98C, with Instance = 0x31C39E90
    Jun 30 13:06:10.080: //4110//AFW_:/AFW_Module_ReturnArgEv: Return List (remove=TRUE){LEG[4110   ][LEG_INCCONNECTED(5)][Cause(0)]}
    Jun 30 13:06:10.080: //4110/CD63A95A81EC/AFW_:/AFW_Object_RemoveListener: 
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_DataArray_ElementDelete: param name LEG_4110
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x31C39E90, Type: Leg, RefCount: 4
    Jun 30 13:06:10.080: //4110//AFW_:/AFW_Module_UnListen:  NumObjects: 0
    Jun 30 13:06:10.080: //4110//Call:/CS_Complete: CallSetup Returning(ls_003 Status CS_NO_RESOURCE)
    Jun 30 13:06:10.080: //4110//AFW_:/AFW_ExecEnv_SetModuleScope: CallSetup_2A696210_0_687505700 ---> NULL
    Jun 30 13:06:10.080: //4110//AFW_:/AFW_Object_WalkListeners:
    Jun 30 13:06:10.080: //4110//AFW_:/AFW_M_Object_ShowListeners: START
    Jun 30 13:06:10.080: //4110//AFW_:/AFW_M_Object_ShowListeners: END
    Jun 30 13:06:10.080: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x30004780, Type: Event, RefCount: 0
    Jun 30 13:06:10.084: //4110//AFW_:/AFW_M_Event_Free: 
    Jun 30 13:06:10.084: //4110//AFW_:/AFW_M_Event_Free:  MODULEDONEEVENT for a Module: Destination_31C3DFF4_0_687505700
    Jun 30 13:06:10.084: //4110//AFW_:/AFW_Object_RemoveAllListener: 
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_M_Object_UnSetExecEnv: ObjCount: 3, CmdPending 3
    Jun 30 13:06:10.084: //4110//AFW_:/AFW_ExecEnv_DecrNPendingCmd:  PendingCmdCount: 2
    Jun 30 13:06:10.084: //-1//AFW_:HN28FA8124:/AFW_M_Event_Free: ExecEnv objCount: 3
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x31C3DFF4, Type: Destination, RefCount: 0
    Jun 30 13:06:10.084: //-1//Dest:HN28FA8124:/AFW_M_Destination_Free: 
    Jun 30 13:06:10.084: //-1//Dest:HN28FA8124:/DestEmptyPreemptHoldQ: 
    Jun 30 13:06:10.084: //-1//OSP :HN28FA8124:/Dest_Settlement_Cleanup: cid(4110) trans=0x0, provider=0
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x2A61C61C, Type: FSM, RefCount: 0
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_M_FSM_Free: 
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x301057A0, Type: FSM, RefCount: 0
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_M_FSM_Free: 
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x2A639380, Type: DataArray, RefCount: 0
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x31D8FA50, Type: DataList, RefCount: 0
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_M_DataList_Free: 
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x31C39E90, Type: Leg, RefCount: 3
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x31D8F988, Type: DataList, RefCount: 0
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_M_DataList_Free: 
    Jun 30 13:06:10.084: //4110//AFW_:/AFW_ExecEnv_CloseIfDone: Cmd Count: 2
    Jun 30 13:06:10.084: //4110//AFW_:/AFW_Event_IsOk: AppEventOk Success - timestamp MATCHED
    Jun 30 13:06:10.084: //4110//AFW_:/AFW_Process_GetPriorityQEvent: Received
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_Process_GetPriorityQEvent:   Event[APP_EV_CALLSETUP_DONE(201)] {
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_Process_GetPriorityQEvent:     EXECENV[0x31D29988]
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_Process_GetPriorityQEvent:     MOD[CallSetup_2A696210_0_687505700]  (
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_Process_GetPriorityQEvent:     )
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_Process_GetPriorityQEvent:   }
    Jun 30 13:06:10.084: //4110//Call:/AFW_M_CallSetup_EventPreProcess: 
    Jun 30 13:06:10.084: //4110//AFW_:/AFW_Object_WalkListeners: 
    Jun 30 13:06:10.084: //4110//AFW_:/AFW_M_Object_ShowListeners: START
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_M_Object_ShowListeners:   MOD[TclModule_313DD624_0_687505696]  (
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_M_Object_ShowListeners:     LEG[4110][LEG_INCCONNECTED(5)][Cause(0)]
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_M_Object_ShowListeners:     MOD[CallSetup_2A696210_0_687505700]  (
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_M_Object_ShowListeners:     )
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_M_Object_ShowListeners:   )
    Jun 30 13:06:10.084: //4110//AFW_:/AFW_M_Object_ShowListeners: END
    Jun 30 13:06:10.084: //4110//AFW_:/AFW_Object_WalkListeners: Entering Module : TclModule
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_DataList_GetFirst: Elem = 0x3006A98C, with Instance = 0x31C39E90
    Jun 30 13:06:10.084: //4110/CD63A95A81EC/AFW_:/AFW_Object_AddListener: adding Module TclModule as listener
    Jun 30 13:06:10.084: //4110//AFW_:/AFW_Object_RemoveListener: 
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_DataArray_ElementDelete: param name CallSetup_2A696210_0_687505700
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x2A696210, Type: CallSetup, RefCount: 1
    Jun 30 13:06:10.084: //4110//AFW_:/AFW_Module_UnListen:  NumObjects: 1
    Jun 30 13:06:10.084: //4110//AFW_:/AFW_ExecEnv_SetModuleScope: NULL ---> TclModule_313DD624_0_687505696
    Jun 30 13:06:10.084: //4110//AFW_:/AFW_M_TclModule_Action: 
    Jun 30 13:06:10.084: //4110//AFW_:/AFW_TclModule_DefaultEvHandling: 
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_Instance_IsType: 0: NULL object
    Jun 30 13:06:10.084: //4110//PACK:/ParamRead:  Reading param med-inact-det from callfeature
    Jun 30 13:06:10.084: //-1//PACK:/ParamRead:  Reading parameter med-inact-det for a script callfeature,
    Jun 30 13:06:10.084: //-1//PACK:/ParamRead:     appRegParams=0x312AE2FC dpParamArray=0x0 pMainParamArray=0x31CE4834
    Jun 30 13:06:10.084: //-1//PACK:/ParamRead:  service level: script callfeature,
    Jun 30 13:06:10.084: //-1//PACK:/ParamRead:     pMainParamArray=0x31CE4834 pMainGroupList=0x0
    Jun 30 13:06:10.084: //-1//PACK:/ParamRead_ElementGetWithGroup:  Looking for param callfeature.med-inact-det
    Jun 30 13:06:10.084: //-1//PACK:/ParamRead_ElementGetWithGroup:  Param callfeature.med-inact-det was not found in this container
    Jun 30 13:06:10.084: //-1//PACK:/ParamRead:  Parameter for the script: callfeature has been read: med-inact-det
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_DataString_Get: 
    Jun 30 13:06:10.084: //4110//PACK:/ParamRead:  Reading param long-dur-call-mon from callfeature
    Jun 30 13:06:10.084: //-1//PACK:/ParamRead:  Reading parameter long-dur-call-mon for a script callfeature,
    Jun 30 13:06:10.084: //-1//PACK:/ParamRead:     appRegParams=0x312AE2FC dpParamArray=0x0 pMainParamArray=0x31CE4834
    Jun 30 13:06:10.084: //-1//PACK:/ParamRead:  service level: script callfeature,
    Jun 30 13:06:10.084: //-1//PACK:/ParamRead:     pMainParamArray=0x31CE4834 pMainGroupList=0x0
    Jun 30 13:06:10.084: //-1//PACK:/ParamRead_ElementGetWithGroup:  Looking for param callfeature.long-dur-call-mon
    Jun 30 13:06:10.084: //-1//PACK:/ParamRead_ElementGetWithGroup:  Param callfeature.long-dur-call-mon was not found in this container
    Jun 30 13:06:10.084: //-1//PACK:/ParamRead:  Parameter for the script: callfeature has been read: long-dur-call-mon
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_DataString_Get: 
    Jun 30 13:06:10.084: //4110//AFW_:/AFW_TclModule_UpdateSessionMask: Update intwrk-mask for leg [4110]'s session
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_ExecEnv_CallProc: Session::SetMask
    Jun 30 13:06:10.084: //4110//AFW_:/AFW_FSM_Drive: ACTION BEGIN: ------(PLACECALL[9],ev_setup_done[201])---[act_CallSetupDone]------
    Jun 30 13:06:10.084: //4110//TCL :/tcl_InfotagObjCmd:  infotag get evt_status
    Jun 30 13:06:10.084: //4110//TCL :/tcl_InfotagGetObjCmd: infotag get evt_status
    Jun 30 13:06:10.084: //4110//AFW_:/vtr_ev_status: argc 2 argindex 2
    Jun 30 13:06:10.084: //4110//TCL :/tcl_InfotagObjCmd:  infotag get evt_status
    Jun 30 13:06:10.084: //4110//TCL :/tcl_InfotagGetObjCmd: infotag get evt_status
    Jun 30 13:06:10.084: //4110//AFW_:/vtr_ev_status: argc 2 argindex 2
    Jun 30 13:06:10.084: //4110//TCL :/tcl_PlayToneObjCmd:  playtone leg_incoming ls_003
    Jun 30 13:06:10.084: //4110//AFW_:/vtd_lg_incoming: argc 3
    Jun 30 13:06:10.084: //4110//AFW_:/vtd_lg_incoming: Legs [4110 ]
    Jun 30 13:06:10.084: //4110//Tcl :/tcl_parseCallID_vartagObj: VARTAG Translation Leg Count=1
    Jun 30 13:06:10.084: //4110/CD63A95A81EC/AFW_:/AFW_Leg_GenerateTone:  ccTone 512 cptone 2
    Jun 30 13:06:10.084: //4110/CD63A95A81EC/AFW_:/AFW_Leg_GetCodec: 
    Jun 30 13:06:10.084: //4110/CD63A95A81EC/AFW_:/AFW_Leg_GetCodec:
    Jun 30 13:06:10.084:  AFW_Leg_GetCodec Using Voice Class Codec, tag = 2

    Jun 30 13:06:10.084: //4110/CD63A95A81EC/AFW_:/AFW_Leg_GenerateToneVOIP: callID 4110  ccTone 512 cptone 2
    Jun 30 13:06:10.084: get_cp_tone_buffer get G729 tone 2 length 500 at 2A08EF64
    Jun 30 13:06:10.084: //4110//MSW :/msw_create: cbf=0x24BA2570
    Jun 30 13:06:10.084: //-1//MSM :MS23:/ms_create: Iniz ply_timer
    Jun 30 13:06:10.084: //4110//MSW :/msw_synth_open: mediaStream 0x300682A8 created
    Jun 30 13:06:10.084: //4110//MSW :/msw_synth_open: rtspStream 0x29B9366C created,
                status=RTSP_STATUS_SUCCESS, session_id=0x17 (23)
    Jun 30 13:06:10.084: //4110//MSW :/msw_synth_open: AIS : Creating TTS AIS Backend record
    Jun 30 13:06:10.084: //-1//MSM :MS24:/ms_create: Iniz ply_timer
    Jun 30 13:06:10.084: //4110//MSW :/msw_recrd_open:
    Jun 30 13:06:10.084: :msw_recrd_open mediaStream 0x31CEA83C created
    Jun 30 13:06:10.084: //4110//MSW :/msw_recrd_open: rtspStream 0x29B93674 created,
                status=RTSP_STATUS_SUCCESS, session_id=0x18 (24)
    Jun 30 13:06:10.084: //4110//MSW :/msw_recog_open: AIS : Creating ASR AIS Backend record
    Jun 30 13:06:10.084: //-1//MSW :/msw_associate_call:
    Jun 30 13:06:10.084: msw_associate_call: callID=0x100E(4110),
                         genericStream=0x296DDDD8
    Jun 30 13:06:10.084: //-1//MCM :MC6:/mc_waitq_unlink: elm=2A64E19C
    Jun 30 13:06:10.084: //-1//MCM :MC6:/mc_waitq_unlink: prompt_wait=0 prompt_active=0

    Jun 30 13:06:10.084: //-1//MCM :MC6:/mc_waitq_delete: prompt_wait=0 prompt_active=1F4
    Jun 30 13:06:10.084: //4110/CD63A95A81EC/AFW_:/AFW_Leg_GenerateToneVOIP: ccTone 512 cptone 2 msw_synth_start for tone://US_g729_tone_congestion codec 16 (req 16) g729
    Jun 30 13:06:10.084: //-1//MSW :/msw_synth_start:
    Jun 30 13:06:10.084: msw_synth_start: Enter...
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_DataList_New: 
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataList(Size=40)
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_DataList_GetWrapper:  Looking for list element 0x313DD624
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_DataList_Enqueue:  Trying to add element to a list
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_DataList_GetWrapper:  Looking for list element 0x313DD624
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_DataList_Enqueue:  Adding element:
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x313DD624, Type: TclModule, RefCount: 3
    Jun 30 13:06:10.084: //4110//MSW :/msw_synth_start: current_stream_id=1, content 0x2A0FC948, dynamicS 0x0, current_state=MSW_S_IDLE
    Jun 30 13:06:10.084: //4110//MSW :/msu_synth_partial_play: Media Stream URL
    Jun 30 13:06:10.084: //4110//MSM :/ms_play: Converting static to dynamic prompting
    Jun 30 13:06:10.084: //-1//DPM :LPP14:MC6:/dp_mc_cnvtDynamicS: convert static prompt OK
    Jun 30 13:06:10.084: //-1//MCM :MR13:/mc_createDynamicReader: 
    Jun 30 13:06:10.084: //4110//MSM :/ms_get_packet_size:
    Jun 30 13:06:10.084:  ms_get_packet_size Using Voice Class Codec, tag = 2

    Jun 30 13:06:10.084: //4110//MSM :/ms_associate: packet_size = 40 timestamp increment = 320 packet_duration = 40 Coder = 16 vad = 0 SampleRate = 8000
    Jun 30 13:06:10.084: //4110//MSM :/ms_associate: >>ccAssociateStream()
    Jun 30 13:06:10.084: //4110//TCL :/tcl_TimerObjCmd:  timer start leg_timer 5 leg_incoming
    Jun 30 13:06:10.084: //4110//TCL :/tcl_TimerStartObjCmd: timer start leg_timer 5 leg_incoming
    Jun 30 13:06:10.084: //4110//AFW_:/vtd_lg_incoming: argc 4
    Jun 30 13:06:10.084: //4110//AFW_:/vtd_lg_incoming: Legs [4110 ]
    Jun 30 13:06:10.084: //4110//Tcl :/tcl_parseCallID_vartagObj: VARTAG Translation Leg Count=1
    Jun 30 13:06:10.084: //4110//TCL :/tcl_FSMObjCmd:  fsm setstate CALLDISCONNECT
    Jun 30 13:06:10.084: //4110//TCL :/tcl_FSMSetStateObjCmd: setstate setstate CALLDISCONNECT
    Jun 30 13:06:10.084: //4110//AFW_:/AFW_FSM_Drive: ACTION END: -------------(CALLDISCONNECT[4])---------------
    Jun 30 13:06:10.084: //4110//AFW_:/AFW_ExecEnv_SetModuleScope: TclModule_313DD624_0_687505696 ---> NULL
    Jun 30 13:06:10.084: //4110//AFW_:/AFW_Object_WalkListeners:
    Jun 30 13:06:10.084: //4110//AFW_:/AFW_M_Object_ShowListeners: START
    Jun 30 13:06:10.084: //4110//AFW_:/AFW_M_Object_ShowListeners: END
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x300084A0, Type: Event, RefCount: 0
    Jun 30 13:06:10.084: //4110//AFW_:/AFW_M_Event_Free: 
    Jun 30 13:06:10.084: //4110//AFW_:/AFW_M_Event_Free:  MODULEDONEEVENT for a Module: CallSetup_2A696210_0_687505700
    Jun 30 13:06:10.084: //4110//AFW_:/AFW_Object_RemoveAllListener: 
    Jun 30 13:06:10.084: //-1//AFW_:/AFW_M_Object_UnSetExecEnv: ObjCount: 2, CmdPending 2
    Jun 30 13:06:10.088: //4110//AFW_:/AFW_ExecEnv_DecrNPendingCmd:  PendingCmdCount: 1
    Jun 30 13:06:10.088: //-1//AFW_:HN28FA8124:/AFW_M_Event_Free: ExecEnv objCount: 2
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x2A696210, Type: CallSetup, RefCount: 0
    Jun 30 13:06:10.088: //-1//Call:HN28FA8124:/AFW_M_CallSetup_Free: 
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x2A61C95C, Type: FSM, RefCount: 0
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_M_FSM_Free: 
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x2A618114, Type: DataArray, RefCount: 0
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x30060010, Type: DataList, RefCount: 0
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_M_DataList_Free: 
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x31C39E90, Type: Leg, RefCount: 2
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x31D8FAA0, Type: DataList, RefCount: 0
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_M_DataList_Free: 
    Jun 30 13:06:10.088: //4110//AFW_:/AFW_ExecEnv_CloseIfDone: Cmd Count: 1
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_Event_New: Event ID: ev_any_event
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: Event(Size=2608)
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_DataList_New: 
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataList(Size=40)
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x30009900, Type: Event, RefCount: 0
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_M_Event_Free: 
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_Instance_IsType: 0: NULL object
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_M_Event_Free: Null or invalid event context: for event APP_EV_NULL
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x31D8FC30, Type: DataList, RefCount: 0
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_M_DataList_Free: 
    Jun 30 13:06:10.088: //4110/CD63A95A81EC/VAAA:0/voip_connect_ccapi_accounting: error: Bad acct_db
    Jun 30 13:06:10.088: //4110//MSM :LP:MS23:/ms_associateDone: 
    Jun 30 13:06:10.088: //4110//MSM :/ms_asDone_buginf: callID=0x100E, pVdb=0x29C689FC,
        disposition=0, playFunc=0x24F98C18,
        codec=0x10=g729r8, vad=0,
        mediaType=1, streamAssocID=4111
    Jun 30 13:06:10.088: //4110//MSM :/ms_associateDone: Setting initial seqnum=6702 for the call
    Jun 30 13:06:10.088: //-1//MCM :MR13:/mc_setup_reader_encaps:  SSRC: 0xFFFFFFFF SeqNum: 0x1A2E
    Jun 30 13:06:10.088: //4110//MSM :/ms_associateDone: First Buf Play at 1w0d of tone://US_g729_tone_congestion
    Jun 30 13:06:10.088: //4110//MSM :/ms_associateDone: 1w0d, Tstart(ply: iSndDly 0)
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_Event_New: Event ID: ev_any_event
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: Event(Size=2608)
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_DataList_New: 
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataList(Size=40)
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x3000A330, Type: Event, RefCount: 0
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_M_Event_Free: 
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_Instance_IsType: 0: NULL object
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_M_Event_Free: Null or invalid event context: for event APP_EV_NULL
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x31D8FC80, Type: DataList, RefCount: 0
    Jun 30 13:06:10.088: //-1//AFW_:/AFW_M_DataList_Free: 
    Jun 30 13:06:10.868: //-1//MCM :MR13:/mc_make_packets_DQ: mc:2A0FC948 name:tone://US_g729_tone_congestion
    Jun 30 13:06:10.868: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 500
    Jun 30 13:06:10.868: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 40
    Jun 30 13:06:10.868: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 460
    Jun 30 13:06:10.868: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 80
    Jun 30 13:06:10.868: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 420
    Jun 30 13:06:10.868: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 120
    Jun 30 13:06:10.868: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 380
    Jun 30 13:06:10.868: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 160
    Jun 30 13:06:10.868: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 340
    Jun 30 13:06:10.868: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 200
    Jun 30 13:06:10.868: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 300
    Jun 30 13:06:10.868: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 240
    Jun 30 13:06:10.868: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 260
    Jun 30 13:06:10.868: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 280
    Jun 30 13:06:10.868: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 220
    Jun 30 13:06:10.868: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 320
    Jun 30 13:06:10.868: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 180
    Jun 30 13:06:10.868: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 360
    Jun 30 13:06:10.868: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 140
    Jun 30 13:06:10.868: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 400
    Jun 30 13:06:10.872: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 100
    Jun 30 13:06:10.872: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 440
    Jun 30 13:06:10.872: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 60
    Jun 30 13:06:10.872: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 480
    Jun 30 13:06:10.872: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 20
    Jun 30 13:06:10.872: //-1//MCM :MR13:/mc_make_packets_DQ: mc_fill_pakList(): status_fillpak 0, /
                          mcr->thisMcBytesPlay 480, mc:2A0FC948 name:tone://US_g729_tone_congestion
    Jun 30 13:06:10.872: //-1//MCM :MR13:/mc_make_packets_DQ: count: 12
    Jun 30 13:06:10.872: //-1//MCM :MR13:/mc_make_packets_DQ: No more prompts to play:
    Jun 30 13:06:10.872: //-1//MCM :MR13:/mc_make_packets_DQ: count: 12
    Jun 30 13:06:10.872: //4110//MSM :/ms_handle_stream_timer: >>ms_start_play()
    Jun 30 13:06:10.872: //4110//MSM :/ms_start_play: 1w0d mgdTstart(rf)
    Jun 30 13:06:10.872: //4110//MSM :/ms_start_play: 1w0d mgdTstop(ply)
    Jun 30 13:06:10.916: //4110//MSM :/ms_play_part: sent: 40, numInBuf: 1400 lastFill: 1440, numBytes: 40
    Jun 30 13:06:10.956: //4110//MSM :/ms_play_part: sent: 40, numInBuf: 1400 lastFill: 1440, numBytes: 40
    Jun 30 13:06:10.996: //4110//MSM :/ms_play_part: sent: 40, numInBuf: 1400 lastFill: 1440, numBytes: 40
    Jun 30 13:06:11.036: //4110//MSM :/ms_play_part: sent: 40, numInBuf: 1400 lastFill: 1440, numBytes: 40
    Jun 30 13:06:11.292: //-1//MCM :/mc_make_packets_DQ: No more on reader
    Jun 30 13:06:11.292: //4110//MSM :/ms_need_packets_more: mgdTstart(rf) at 1w0d
    Jun 30 13:06:11.296: //4110//MSM :/ms_play_part: sent: 200, numInBuf: 1220 lastFill: 1420, numBytes: 220
    Jun 30 13:06:11.336: //4110//MSM :/ms_play_part: sent: 40, numInBuf: 1380 lastFill: 1420, numBytes: 40
    Jun 30 13:06:11.376: //4110//MSM :/ms_play_part: sent: 40, numInBuf: 1380 lastFill: 1420, numBytes: 40
    Jun 30 13:06:11.376: //4110//MSM :/ms_process: $w$ intEvent MS_E_STOP_PLAY
    Jun 30 13:06:11.376: //4110//MSM :/ms_stop_play: mgdTstop at 1w0d (cause MS_STOP_COMPLETE)
    Jun 30 13:06:11.376: //4110//MSM :/ms_stop_play: mgdTstop(rf) at 1w0d
    Jun 30 13:06:11.376: //4110//MSM :/ms_restart_prompt: Restarting the prompt for > 1 repetions..as it got cutoff
    Jun 30 13:06:11.376: //4110//MSM :/ms_cutoff: 1w0d Tstop
    Jun 30 13:06:11.376: //4110//MSM :/ms_cutoff: play cutoff at 1w0d
    Jun 30 13:06:11.376: //-1//MCM :MR13:/mc_make_packets_DQ: mc:2A0FC948 name:tone://US_g729_tone_congestion
    Jun 30 13:06:11.376: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 500
    Jun 30 13:06:11.376: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 40
    Jun 30 13:06:11.376: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 460
    Jun 30 13:06:11.376: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 80
    Jun 30 13:06:11.376: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 420
    Jun 30 13:06:11.376: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 120
    Jun 30 13:06:11.376: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 380
    Jun 30 13:06:11.376: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 160
    Jun 30 13:06:11.376: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 340
    Jun 30 13:06:11.376: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 200
    Jun 30 13:06:11.376: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 300
    Jun 30 13:06:11.376: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 240
    Jun 30 13:06:11.376: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 260
    Jun 30 13:06:11.376: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 280
    Jun 30 13:06:11.376: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 220
    Jun 30 13:06:11.376: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 320
    Jun 30 13:06:11.376: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 180
    Jun 30 13:06:11.376: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 360
    Jun 30 13:06:11.376: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 140
    Jun 30 13:06:11.376: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 400
    Jun 30 13:06:11.376: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 100
    Jun 30 13:06:11.376: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 440
    Jun 30 13:06:11.376: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 60
    Jun 30 13:06:11.376: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 480
    Jun 30 13:06:11.376: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 20
    Jun 30 13:06:11.376: //-1//MCM :MR13:/mc_make_packets_DQ: mc_fill_pakList(): status_fillpak 0, /
                          mcr->thisMcBytesPlay 480, mc:2A0FC948 name:tone://US_g729_tone_congestion
    Jun 30 13:06:11.376: //-1//MCM :MR13:/mc_make_packets_DQ: count: 12
    Jun 30 13:06:11.376: //-1//MCM :MR13:/mc_make_packets_DQ: No more prompts to play:
    Jun 30 13:06:11.376: //-1//MCM :MR13:/mc_make_packets_DQ: count: 12
    Jun 30 13:06:11.376: //4110//MSM :/ms_cutoff: First Buf Play at 1w0d of tone://US_g729_tone_congestion
    Jun 30 13:06:11.376: //4110//MSM :/ms_cutoff: ms_cutoff() 1w0d, Tstart(iSndDly 0)
    Jun 30 13:06:11.376: //4110//MSM :/ms_process: >>ms_delete_event(MS_E_int)
    Jun 30 13:06:12.204: //4110//MSM :/ms_handle_stream_timer: >>ms_start_play()
    Jun 30 13:06:12.204: //4110//MSM :/ms_start_play: 1w0d mgdTstart(rf)
    Jun 30 13:06:12.204: //4110//MSM :/ms_start_play: 1w0d mgdTstop(ply)
    Jun 30 13:06:12.248: //4110//MSM :/ms_play_part: sent: 40, numInBuf: 1400 lastFill: 1440, numBytes: 40
    Jun 30 13:06:12.288: //4110//MSM :/ms_play_part: sent: 40, numInBuf: 1400 lastFill: 1440, numBytes: 40
    Jun 30 13:06:12.328: //4110//MSM :/ms_play_part: sent: 40, numInBuf: 1400 lastFill: 1440, numBytes: 40
    Jun 30 13:06:12.368: //4110//MSM :/ms_play_part: sent: 40, numInBuf: 1400 lastFill: 1440, numBytes: 40
    Jun 30 13:06:12.916: //-1//MCM :/mc_make_packets_DQ: No more on reader
    Jun 30 13:06:12.916: //4110//MSM :/ms_need_packets_more: mgdTstart(rf) at 1w0d
    Jun 30 13:06:12.920: //4110//MSM :/ms_play_part: sent: 320, numInBuf: 928 lastFill: 1248, numBytes: 512
    Jun 30 13:06:12.920: //4110//MSM :/ms_process: $w$ intEvent MS_E_STOP_PLAY
    Jun 30 13:06:12.920: //4110//MSM :/ms_stop_play: mgdTstop at 1w0d (cause MS_STOP_COMPLETE)
    Jun 30 13:06:12.920: //4110//MSM :/ms_stop_play: mgdTstop(rf) at 1w0d
    Jun 30 13:06:12.920: //4110//MSM :/ms_restart_prompt: Restarting the prompt for > 1 repetions..as it got cutoff
    Jun 30 13:06:12.920: //4110//MSM :/ms_cutoff: 1w0d Tstop
    Jun 30 13:06:12.920: //4110//MSM :/ms_cutoff: play cutoff at 1w0d
    Jun 30 13:06:12.920: //-1//MCM :MR13:/mc_make_packets_DQ: mc:2A0FC948 name:tone://US_g729_tone_congestion
    Jun 30 13:06:12.920: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 500
    Jun 30 13:06:12.920: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 40
    Jun 30 13:06:12.920: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 460
    Jun 30 13:06:12.920: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 80
    Jun 30 13:06:12.920: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 420
    Jun 30 13:06:12.920: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 120
    Jun 30 13:06:12.920: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 380
    Jun 30 13:06:12.920: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 160
    Jun 30 13:06:12.920: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 340
    Jun 30 13:06:12.920: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 200
    Jun 30 13:06:12.920: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 300
    Jun 30 13:06:12.920: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 240
    Jun 30 13:06:12.920: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 260
    Jun 30 13:06:12.920: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 280
    Jun 30 13:06:12.920: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 220
    Jun 30 13:06:12.920: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 320
    Jun 30 13:06:12.920: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 180
    Jun 30 13:06:12.920: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 360
    Jun 30 13:06:12.920: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 140
    Jun 30 13:06:12.920: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 400
    Jun 30 13:06:12.920: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 100
    Jun 30 13:06:12.920: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 440
    Jun 30 13:06:12.920: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 60
    Jun 30 13:06:12.920: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 480
    Jun 30 13:06:12.920: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 20
    Jun 30 13:06:12.920: //-1//MCM :MR13:/mc_make_packets_DQ: mc_fill_pakList(): status_fillpak 0, /
                          mcr->thisMcBytesPlay 480, mc:2A0FC948 name:tone://US_g729_tone_congestion
    Jun 30 13:06:12.920: //-1//MCM :MR13:/mc_make_packets_DQ: count: 12
    Jun 30 13:06:12.920: //-1//MCM :MR13:/mc_make_packets_DQ: No more prompts to play:
    Jun 30 13:06:12.920: //-1//MCM :MR13:/mc_make_packets_DQ: count: 12
    Jun 30 13:06:12.920: //4110//MSM :/ms_cutoff: First Buf Play at 1w0d of tone://US_g729_tone_congestion
    Jun 30 13:06:12.920: //4110//MSM :/ms_cutoff: ms_cutoff() 1w0d, Tstart(iSndDly 0)
    Jun 30 13:06:12.920: //4110//MSM :/ms_process: >>ms_delete_event(MS_E_int)
    Jun 30 13:06:13.752: //4110//MSM :/ms_handle_stream_timer: >>ms_start_play()
    Jun 30 13:06:13.752: //4110//MSM :/ms_start_play: 1w0d mgdTstart(rf)
    Jun 30 13:06:13.752: //4110//MSM :/ms_start_play: 1w0d mgdTstop(ply)
    Jun 30 13:06:13.796: //4110//MSM :/ms_play_part: sent: 40, numInBuf: 1400 lastFill: 1440, numBytes: 40
    Jun 30 13:06:13.836: //4110//MSM :/ms_play_part: sent: 40, numInBuf: 1400 lastFill: 1440, numBytes: 40
    Jun 30 13:06:13.876: //4110//MSM :/ms_play_part: sent: 40, numInBuf: 1400 lastFill: 1440, numBytes: 40
    Jun 30 13:06:13.916: //4110//MSM :/ms_play_part: sent: 40, numInBuf: 1400 lastFill: 1440, numBytes: 40
    Jun 30 13:06:14.408: //-1//MCM :/mc_make_packets_DQ: No more on reader
    Jun 30 13:06:14.408: //4110//MSM :/ms_need_packets_more: mgdTstart(rf) at 1w0d
    Jun 30 13:06:14.416: //4110//MSM :/ms_play_part: sent: 320, numInBuf: 980 lastFill: 1300, numBytes: 460
    Jun 30 13:06:14.416: //4110//MSM :/ms_process: $w$ intEvent MS_E_STOP_PLAY
    Jun 30 13:06:14.416: //4110//MSM :/ms_stop_play: mgdTstop at 1w0d (cause MS_STOP_COMPLETE)
    Jun 30 13:06:14.416: //4110//MSM :/ms_stop_play: mgdTstop(rf) at 1w0d
    Jun 30 13:06:14.416: //4110//MSM :/ms_restart_prompt: Restarting the prompt for > 1 repetions..as it got cutoff
    Jun 30 13:06:14.416: //4110//MSM :/ms_cutoff: 1w0d Tstop
    Jun 30 13:06:14.416: //4110//MSM :/ms_cutoff: play cutoff at 1w0d
    Jun 30 13:06:14.416: //-1//MCM :MR13:/mc_make_packets_DQ: mc:2A0FC948 name:tone://US_g729_tone_congestion
    Jun 30 13:06:14.416: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 500
    Jun 30 13:06:14.416: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 40
    Jun 30 13:06:14.416: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 460
    Jun 30 13:06:14.416: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 80
    Jun 30 13:06:14.416: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 420
    Jun 30 13:06:14.416: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 120
    Jun 30 13:06:14.416: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 380
    Jun 30 13:06:14.416: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 160
    Jun 30 13:06:14.416: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 340
    Jun 30 13:06:14.416: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 200
    Jun 30 13:06:14.416: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 300
    Jun 30 13:06:14.416: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 240
    Jun 30 13:06:14.416: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 260
    Jun 30 13:06:14.416: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 280
    Jun 30 13:06:14.416: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 220
    Jun 30 13:06:14.416: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 320
    Jun 30 13:06:14.416: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 180
    Jun 30 13:06:14.416: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 360
    Jun 30 13:06:14.416: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 140
    Jun 30 13:06:14.416: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 400
    Jun 30 13:06:14.416: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 100
    Jun 30 13:06:14.416: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 440
    Jun 30 13:06:14.416: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 60
    Jun 30 13:06:14.416: //-1//MCM :MC6:/mc_make_nohdr_packet: (enough data), current_buf: 0x31A6E5A4 thisMcBytesPlayed: 480
    Jun 30 13:06:14.416: //-1//MCM :MC6:/mc_make_nohdr_packet: mc->name tone://US_g729_tone_congestion, bytesLeftInBuf: 20
    Jun 30 13:06:14.416: //-1//MCM :MR13:/mc_make_packets_DQ: mc_fill_pakList(): status_fillpak 0, /
                          mcr->thisMcBytesPlay 480, mc:2A0FC948 name:tone://US_g729_tone_congestion
    Jun 30 13:06:14.416: //-1//MCM :MR13:/mc_make_packets_DQ: count: 12
    Jun 30 13:06:14.416: //-1//MCM :MR13:/mc_make_packets_DQ: No more prompts to play:
    Jun 30 13:06:14.416: //-1//MCM :MR13:/mc_make_packets_DQ: count: 12
    Jun 30 13:06:14.416: //4110//MSM :/ms_cutoff: First Buf Play at 1w0d of tone://US_g729_tone_congestion
    Jun 30 13:06:14.416: //4110//MSM :/ms_cutoff: ms_cutoff() 1w0d, Tstart(iSndDly 0)
    Jun 30 13:06:14.416: //4110//MSM :/ms_process: >>ms_delete_event(MS_E_int)
    Jun 30 13:06:15.236: //4110//MSM :/ms_handle_stream_timer: >>ms_start_play()
    Jun 30 13:06:15.236: //4110//MSM :/ms_start_play: 1w0d mgdTstart(rf)
    Jun 30 13:06:15.236: //4110//MSM :/ms_start_play: 1w0d mgdTstop(ply)
    Jun 30 13:06:15.236: //-1//AFW_:/AFW_Event_New: Event ID: ev_any_event
    Jun 30 13:06:15.236: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: Event(Size=2608)
    Jun 30 13:06:15.236: //-1//AFW_:/AFW_DataList_New: 
    Jun 30 13:06:15.236: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataList(Size=40)
    Jun 30 13:06:15.236: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x3000AD60, Type: Event, RefCount: 0
    Jun 30 13:06:15.236: //-1//AFW_:/AFW_M_Event_Free: 
    Jun 30 13:06:15.236: //-1//AFW_:/AFW_Instance_IsType: 0: NULL object
    Jun 30 13:06:15.236: //-1//AFW_:/AFW_M_Event_Free: Null or invalid event context: for event APP_EV_NULL
    Jun 30 13:06:15.236: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x31D8F9B0, Type: DataList, RefCount: 0
    Jun 30 13:06:15.236: //-1//AFW_:/AFW_M_DataList_Free: 
    Jun 30 13:06:15.236: //-1//AFW_:/AFW_Event_New: Event ID: ev_leg_timer
    Jun 30 13:06:15.236: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: Event(Size=2608)
    Jun 30 13:06:15.236: //-1//AFW_:/AFW_DataList_New: 
    Jun 30 13:06:15.236: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataList(Size=40)
    Jun 30 13:06:15.236: //4110/CD63A95A81EC/AFW_:/AFW_Process_GetTimerEvent: Received
    Jun 30 13:06:15.236: //-1//AFW_:/AFW_Process_GetTimerEvent:   Event[APP_EV_LEG_TIMER(1)] {
    Jun 30 13:06:15.236: //-1//AFW_:/AFW_Process_GetTimerEvent:     EXECENV[0x31D29988]
    Jun 30 13:06:15.236: //-1//AFW_:/AFW_Process_GetTimerEvent:     LEG[4110][LEG_INCCONNECTED(5)][Cause(0)]
    Jun 30 13:06:15.236: //-1//AFW_:/AFW_Process_GetTimerEvent:   }
    Jun 30 13:06:15.236: //-1//SSIN:/AFW_SS_MapEvent: No mapping required
    Jun 30 13:06:15.236: //4110/CD63A95A81EC/AFW_:/AFW_M_Leg_EventPreProcess: LEG[4110   ][LEG_INCCONNECTED(5)][Cause(0)]
    Jun 30 13:06:15.236: //4110/CD63A95A81EC/AFW_:/AFW_Object_WalkListeners: 
    Jun 30 13:06:15.236: //4110/CD63A95A81EC/AFW_:/AFW_M_Object_ShowListeners: START
    Jun 30 13:06:15.236: //-1//AFW_:/AFW_M_Object_ShowListeners:   MOD[TclModule_313DD624_0_687505696]  (
    Jun 30 13:06:15.236: //-1//AFW_:/AFW_M_Object_ShowListeners:     LEG[4110][LEG_INCCONNECTED(5)][Cause(0)]
    Jun 30 13:06:15.236: //-1//AFW_:/AFW_M_Object_ShowListeners:   )
    Jun 30 13:06:15.236: //4110/CD63A95A81EC/AFW_:/AFW_M_Object_ShowListeners: END
    Jun 30 13:06:15.236: //4110/CD63A95A81EC/AFW_:/AFW_Object_WalkListeners: Entering Module : TclModule
    Jun 30 13:06:15.236: //4110//AFW_:/AFW_ExecEnv_SetModuleScope: NULL ---> TclModule_313DD624_0_687505696
    Jun 30 13:06:15.236: //4110//AFW_:/AFW_M_TclModule_Action: 
    Jun 30 13:06:15.236: //4110//AFW_:/AFW_TclModule_DefaultEvHandling: 
    Jun 30 13:06:15.236: //4110//AFW_:/AFW_FSM_Drive: ACTION BEGIN: ------(CALLDISCONNECT[4],ev_leg_timer[1])---[act_Cleanup]------
    Jun 30 13:06:15.236: //4110//TCL :/tcl_CallObjCmd:  call close
    Jun 30 13:06:15.236: //4110//TCL :/tcl_CallCloseObjCmd:  close
    Jun 30 13:06:15.236: //-1//AFW_:/AFW_ExecEnv_CallClose:  Exec Env state: 1
    Jun 30 13:06:15.236: //-1//AFW_:/AFW_ExecEnv_CallClose:  Terminating ExecEnv's root module
    Jun 30 13:06:15.240: //4110//AFW_:/AFW_Module_Terminate:  Terminating Module: TclModule_313DD624_0_687505696
    Jun 30 13:06:15.240: //4110//AFW_:/AFW_M_TclModule_Terminate:  Module is in the state: ACTIVE
    Jun 30 13:06:15.240: //4110//AFW_:/AFW_TclModule_Cleaner: lastFailureCause 3
    Jun 30 13:06:15.240: //4110/CD63A95A81EC/AFW_:/AFW_Leg_Disconnect: Disconnecting Leg: LEG_4110
    Jun 30 13:06:15.240: //4110/CD63A95A81EC/AFW_:/AFW_Leg_Disconnect: Disconnecting Leg: LEG_4110, Cause 16
    Jun 30 13:06:15.240: //-1//MSW :/msw_stop: genericStream=0x296DDDD8,
                   reason=MSW_REASON_DISCONNECTED
    Jun 30 13:06:15.240: //-1//MSW :/msw_synth_stop: msw_synth_stop: Enter...
    Jun 30 13:06:15.240: //-1//MSW :/msw_synth_stop: genericStream=0x296DDDD8,
                   mediaStream=0x300682A8, rtspStream=0x29B9366C
                   reason=MSW_SYNTH_REASON_DISCONNECTED, current_state=MSW_S_PLAYING
    Jun 30 13:06:15.240: //4110//MSW :/msw_synth_stop: msw_synth_stop: call ms_stop_play()...
    Jun 30 13:06:15.240: //4110//MSM :/ms_stop_play: mgdTstop at 1w0d (cause MS_STOP_DISCONNECTED)
    Jun 30 13:06:15.240: //4110//MSM :/ms_stop_play: mgdTstop(rf) at 1w0d
    Jun 30 13:06:15.240: //4110//MSM :/ms_stop_play: Play Stopped at 1w0d
    Jun 30 13:06:15.240: //4110//MSM :/ms_stop_play: calling CBF for stream_id 1
    Jun 30 13:06:15.240: //4110//MSW :/msu_synth_ms_play_complete: context=0x296DDDDC, use_dynamic=0, dynamicElement=0x0,
                cause=MS_STOP_DISCONNECTED, stream_id=1, duration=500, rate=0 proto_code=0
    Jun 30 13:06:15.240: //4110//MSW :/msu_synth_ms_play_complete: Ignoring: cur. stream=2, resp. stream=1
    Jun 30 13:06:15.240: //-1//DPM P14:/dp_delete_mcDynamicS: >dequeue(mcDynamicQ)
    Jun 30 13:06:15.240: //-1//MCM :MC6:/mc_delete: mc=0x2A0FC948
    Jun 30 13:06:15.240: //-1//MCM :MC6:/mc_delete: refCount=1
    Jun 30 13:06:15.240: //-1//MCM :MC6:/mc_check_background_load: mc(0x2A0FC948), mc->eof=1
    Jun 30 13:06:15.240: //-1//MCM :MC6:/mc_waitq_add: prompt_wait=1F4 prompt_active=0
    Jun 30 13:06:15.240: //-1//DPM P14:/dp_delete_mcDynamicS: >free(p_mcDynamicS)
    Jun 30 13:06:15.240: //-1//MCM :MR13:/mc_delete_read: dequeue(pakList)
    Jun 30 13:06:15.240: //-1//MSW :/msw_recrd_stop: genericStream=0x296DDDD8,
                   mediaStream=0x31CEA83C, rtspStream=0x29B93674
                   reason=MSW_RECRD_REASON_DISCONNECTED current_state=MSW_S_IDLE
    Jun 30 13:06:15.240: //-1//MSW :/msw_recrd_stop: Stream not currently active
    Jun 30 13:06:15.240: //-1//MSW :/msw_recog_stop:
    Jun 30 13:06:15.240: msw_recog_stop: genericStream=0x296DDDD8,
                   mrcpStream=0x29B936F8
                   reason=MSW_RECOG_REASON_DISCONNECTED, current_state=MSW_S_IDLE
    Jun 30 13:06:15.240: //-1//AFW_:/afw_get_mapped_disc_cause: Mapping requested for Q850 cause (16)
    Jun 30 13:06:15.240: //-1//AFW_:/afw_get_mapped_disc_cause: Mapping not found for Q850 cause(16)
    Jun 30 13:06:15.240: //4110/CD63A95A81EC/AFW_:/AFW_Leg_UpdateStats: Updating stats for ID 842 type 2
    Jun 30 13:06:15.240: //-1//VAAA:0/voip_start_ccapi_rotary_accounting: WARNING: gw-accounting aaa not enabled. return.
    Jun 30 13:06:15.240: //4110//AFW_:/AFW_FSM_Drive: ACTION END: -------------(samestate[5])---------------
    Jun 30 13:06:15.240: //4110//AFW_:/AFW_ExecEnv_SetModuleScope: TclModule_313DD624_0_687505696 ---> NULL
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x3000B790, Type: Event, RefCount: 0
    Jun 30 13:06:15.240: //4110/CD63A95A81EC/AFW_:/AFW_M_Event_Free: 
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x31D8FC08, Type: DataList, RefCount: 0
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_M_DataList_Free: 
    Jun 30 13:06:15.240: //4110//AFW_:/AFW_ExecEnv_CloseIfDone: Cmd Count: 1
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_Event_New: Event ID: ev_any_event
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: Event(Size=2608)
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_DataList_New: 
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataList(Size=40)
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x30008ED0, Type: Event, RefCount: 0
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_M_Event_Free: 
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_Instance_IsType: 0: NULL object
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_M_Event_Free: Null or invalid event context: for event APP_EV_NULL
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x31D8FBE0, Type: DataList, RefCount: 0
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_M_DataList_Free: 
    Jun 30 13:06:15.240: //4110/CD63A95A81EC/VAAA:0/voip_stop_ccapi_accounting: (4110): UID=0
    Jun 30 13:06:15.240: //4110/CD63A95A81EC/VAAA:0/voip_stop_ccapi_accounting: error: Bad acct_db
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_Event_New: Event ID: ev_any_event
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: Event(Size=2608)
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_DataList_New: 
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataList(Size=40)
    Jun 30 13:06:15.240: //4110/CD63A95A81EC/AFW_:/AFW_Process_GetCcqEvent: Received
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_Process_GetCcqEvent:   Event[CC_EV_CALL_DISCONNECT_DONE(19)] {
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_Process_GetCcqEvent:     EXECENV[0x31D29988]
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_Process_GetCcqEvent:     LEG[4110][LEG_INCDISCONNECTING(6)][Cause(16)]
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_Process_GetCcqEvent:   }
    Jun 30 13:06:15.240: //-1//SSIN:/AFW_SS_MapEvent: No mapping required
    Jun 30 13:06:15.240: //4110/CD63A95A81EC/AFW_:/AFW_Object_WalkListeners: 
    Jun 30 13:06:15.240: //4110/CD63A95A81EC/AFW_:/AFW_M_Object_ShowListeners: START
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_M_Object_ShowListeners:   MOD[TclModule_313DD624_0_687505696]  (
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_M_Object_ShowListeners:     LEG[4110][LEG_DISCONNECTED(12)][Cause(16)]
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_M_Object_ShowListeners:   )
    Jun 30 13:06:15.240: //4110/CD63A95A81EC/AFW_:/AFW_M_Object_ShowListeners: END
    Jun 30 13:06:15.240: //4110/CD63A95A81EC/AFW_:/AFW_Object_WalkListeners: Entering Module : TclModule
    Jun 30 13:06:15.240: //4110/CD63A95A81EC/AFW_:/AFW_Object_RemoveListener: 
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_DataArray_ElementDelete: param name LEG_4110
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x31C39E90, Type: Leg, RefCount: 1
    Jun 30 13:06:15.240: //4110//AFW_:/AFW_Module_UnListen:  NumObjects: 0
    Jun 30 13:06:15.240: //4110//AFW_:/AFW_ExecEnv_SetModuleScope: NULL ---> TclModule_313DD624_0_687505696
    Jun 30 13:06:15.240: //4110//AFW_:/AFW_M_TclModule_Action: 
    Jun 30 13:06:15.240: //4110//AFW_:/AFW_M_TclModule_Action: Module is Terminating
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_Event_New: Event ID: ev_module_done
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: Event(Size=2608)
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_DataList_New: 
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataList(Size=40)
    Jun 30 13:06:15.240: //4110//AFW_:/AFW_TclModule_ReturnIfDone:  Sending Out APP_EV_TCLMODULE_DONE event
    Jun 30 13:06:15.240: //4110//AFW_:/AFW_Module_ReturnArgEv: 
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_DataList_New: 
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataList(Size=40)
    Jun 30 13:06:15.240: //4110//AFW_:/AFW_ExecEnv_SetModuleScope: TclModule_313DD624_0_687505696 ---> NULL
    Jun 30 13:06:15.240: //4110/CD63A95A81EC/AFW_:/AFW_Object_WalkListeners:
    Jun 30 13:06:15.240: //4110/CD63A95A81EC/AFW_:/AFW_M_Object_ShowListeners: START
    Jun 30 13:06:15.240: //4110/CD63A95A81EC/AFW_:/AFW_M_Object_ShowListeners: END
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x3000C1C0, Type: Event, RefCount: 0
    Jun 30 13:06:15.240: //4110/CD63A95A81EC/AFW_:/AFW_M_Event_Free: 
    Jun 30 13:06:15.240: //4110/CD63A95A81EC/AFW_:/AFW_M_Event_Free:  CC_EV_CALL_DISCONNECT_DONE for a Leg: LEG_4110
    Jun 30 13:06:15.240: //4110/CD63A95A81EC/AFW_:/AFW_Object_RemoveAllListener: 
    Jun 30 13:06:15.240: //4110//AFW_:/AFW_ExecEnv_DecrNPendingCmd:  PendingCmdCount: 0
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_M_Object_UnSetExecEnv: ObjCount: 1, CmdPending 0
    Jun 30 13:06:15.240: //4110/CD63A95A81EC/AFW_:/AFW_M_Event_Free: ExecEnv objCount: 1
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x31C39E90, Type: Leg, RefCount: 0
    Jun 30 13:06:15.240: //4110/CD63A95A81EC/AFW_:/AFW_M_Leg_Free: 
    Jun 30 13:06:15.240: //4110//MSW :/msw_destroy: 
    Jun 30 13:06:15.240: //-1//MSW :/msw_stop: genericStream=0x296DDDD8,
                   reason=MSW_REASON_DISCONNECTED
    Jun 30 13:06:15.240: //-1//MSW :/msw_synth_stop: msw_synth_stop: Enter...
    Jun 30 13:06:15.240: //-1//MSW :/msw_synth_stop: genericStream=0x296DDDD8,
                   mediaStream=0x300682A8, rtspStream=0x29B9366C
                   reason=MSW_SYNTH_REASON_DISCONNECTED, current_state=MSW_S_IDLE
    Jun 30 13:06:15.240: //4110//MSW :/msw_synth_stop: Stream not currently active
    Jun 30 13:06:15.240: //-1//MSW :/msw_recrd_stop: genericStream=0x296DDDD8,
                   mediaStream=0x31CEA83C, rtspStream=0x29B93674
                   reason=MSW_RECRD_REASON_DISCONNECTED current_state=MSW_S_IDLE
    Jun 30 13:06:15.240: //-1//MSW :/msw_recrd_stop: Stream not currently active
    Jun 30 13:06:15.240: //-1//MSW :/msw_recog_stop:
    Jun 30 13:06:15.240: msw_recog_stop: genericStream=0x296DDDD8,
                   mrcpStream=0x29B936F8
                   reason=MSW_RECOG_REASON_DISCONNECTED, current_state=MSW_S_IDLE
    Jun 30 13:06:15.240: //-1//MSW :/msw_synth_stop: msw_synth_stop: Enter...
    Jun 30 13:06:15.240: //-1//MSW :/msw_synth_stop: genericStream=0x296DDDD8,
                   mediaStream=0x300682A8, rtspStream=0x29B9366C
                   reason=MSW_SYNTH_REASON_DISCONNECTED, current_state=MSW_S_IDLE
    Jun 30 13:06:15.240: //4110//MSW :/msw_synth_stop: Stream not currently active
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x31D8F9D8, Type: DataList, RefCount: 0
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_M_DataList_Free: 
    Jun 30 13:06:15.240: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x313DD624, Type: TclModule, RefCount: 2
    Jun 30 13:06:15.240: //-1//MSW :/msw_recrd_stop: genericStream=0x296DDDD8,
                   mediaStream=0x31CEA83C, rtspStream=0x29B93674
                   reason=MSW_RECRD_REASON_DISCONNECTED current_state=MSW_S_IDLE
    Jun 30 13:06:15.244: //-1//MSW :/msw_recrd_stop: Stream not currently active
    Jun 30 13:06:15.244: //-1//MSW :/msw_recog_stop:
    Jun 30 13:06:15.244: msw_recog_stop: genericStream=0x296DDDD8,
                   mrcpStream=0x29B936F8
                   reason=MSW_RECOG_REASON_DISCONNECTED, current_state=MSW_S_IDLE
    Jun 30 13:06:15.244: //4110/CD63A95A81EC/AFW_:/decrementDialPeerCallStats: Decrementing call-stat for disconnecting leg, dial-peer [10]
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x31D8FA00, Type: DataList, RefCount: 0
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_M_DataList_Free: 
    Jun 30 13:06:15.244: //4110//AFW_:/AFW_ExecEnv_CloseIfDone: Cmd Count: 0
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_ExecEnv_CallClose:  Exec Env state: 3
    Jun 30 13:06:15.244: //4110//AFW_:/AFW_Event_IsOk: AppEventOk Success - timestamp MATCHED
    Jun 30 13:06:15.244: //4110//AFW_:/AFW_Process_GetPriorityQEvent: Received
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_Process_GetPriorityQEvent:   Event[APP_EV_TCLMODULE_DONE(220)] {
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_Process_GetPriorityQEvent:     EXECENV[0x31D29988]
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_Process_GetPriorityQEvent:     MOD[TclModule_313DD624_0_687505696]  (
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_Process_GetPriorityQEvent:     )
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_Process_GetPriorityQEvent:   }
    Jun 30 13:06:15.244: //4110//AFW_:/AFW_M_TclModule_EventPreProcess: 
    Jun 30 13:06:15.244: //4110//AFW_:/AFW_Object_WalkListeners: 
    Jun 30 13:06:15.244: //4110//AFW_:/AFW_M_Object_ShowListeners: START
    Jun 30 13:06:15.244: //4110//AFW_:/AFW_M_Object_ShowListeners: END
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x30000030, Type: Event, RefCount: 0
    Jun 30 13:06:15.244: //4110//AFW_:/AFW_M_Event_Free: 
    Jun 30 13:06:15.244: //4110//AFW_:/AFW_M_Event_Free:  MODULEDONEEVENT for a Module: TclModule_313DD624_0_687505696
    Jun 30 13:06:15.244: //4110//AFW_:/AFW_Object_RemoveAllListener: 
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_M_Object_UnSetExecEnv: ObjCount: 0, CmdPending 0
    Jun 30 13:06:15.244: //-1//AFW_:HN28FA8120:/AFW_M_Event_Free: ExecEnv objCount: 0
    Jun 30 13:06:15.244: //-1//SERV:/AFW_Service_ReleaseExecEnv: Script Name = auth cache = true calls = 0
    Jun 30 13:06:15.244: //4110//AFW_:/AFW_ExecEnv_UnSetRoot: Execenv = 0x31D29988
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_Process_UnLock: pProcess(0x3144788C)=0
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x3144788C, Type: Process, RefCount: 1
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x30116784, Type: DataArray, RefCount: 0
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x2A658E3C, Type: DataString, RefCount: 0
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x30054A78, Type: DataString, RefCount: 0
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x31D41970, Type: DataArray, RefCount: 0
    Jun 30 13:06:15.244: //-1//SCRI:/cam_sa_stopped: Instance: [] ExecEnv: 0x31D29988
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_DataList_Requeue:  Trying to add element to a list
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_DataList_GetWrapper:  Looking for list element 0x31D29988
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_DataList_Requeue:  Adding element:
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_Instance_IncrRefCount: Object: 0x31D29988, Type: ExecEnv, RefCount: 2
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x313DD624, Type: TclModule, RefCount: 1
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x31D8FB40, Type: DataList, RefCount: 0
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_M_DataList_Free: 
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x31D8FA78, Type: DataList, RefCount: 0
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_M_DataList_Free: 
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_Event_New: Event ID: ev_any_event
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: Event(Size=2608)
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_DataList_New: 
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_Class_Allocate: Malloc Data Space: DataList(Size=40)
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x30000A60, Type: Event, RefCount: 0
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_M_Event_Free: 
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_Instance_IsType: 0: NULL object
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_M_Event_Free: Null or invalid event context: for event APP_EV_NULL
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_Instance_DecrRefCount: Object: 0x31D8FBB8, Type: DataList, RefCount: 0
    Jun 30 13:06:15.244: //-1//AFW_:/AFW_M_DataList_Free: 
    Jun 30 13:06:19.096: //-1//SCRI:/ScriptList_CacheCurrent:  auth



    If I remove the service from the dial-peer in my configuration, the call completes normally using outbound peer 100. I can tell from this debug log that the TCL script alos selects the same outbound peer, but the call fails.

    Subject: RE: authentication problem
    Replied by: Anusha Kannappan on 01-07-2011 05:41:38 AM
    Hi Wesley,

    With regard to the error you are getting, as the authentication is failed the user is denied access and gateway is blocking the call due to which you are not able to complete the call when the service is configured in the dial-peer. Here is the detailed information of the error you received.

    ASG_3845#sh voice iec description 1.1.228.11.32.0
        IEC Version: 1
        Entity: 1 (Gateway)
        Category: 228 (User is denied access to this service)
        Subsystem: 11 (C SCRIPTS)
        Error: 32 (OSP Fail)
        Diagnostic Code: 0

    I don't think there is any way to set any variable to make the authentication as succeeded in this scenario. But anyway I will cross check with our internal teams over here and keep posted once I receive any updates on the same.

    Thanks,
    Anusha

    Subject: RE: authentication problem
    Replied by: WESLEY PHILLIPS on 04-08-2011 02:43:36 PM
    I have been able to "sort of" find a solution to this. Since the gateway is incapable of connecting a call when the authentication fails, I will have to stand up a second radius server, configure it on the router, and then rely on redundant servers, so that there is never an instance where the server is "unavailable(au_001)".


    Thanks

    Wes