TServer_ivr_7.5 with mps3.0 Driver for Periphonics - Call keys not available

[bogdan]

Hello,

After installation and configuration of TServerIVR (7.5), IServer and compiled new TLibs(7.5) and the new IVRDriver (7.5) it seems the driver can not get ANI and DNIS parameters from the IServer.

[code]
(...snipp from ivr_driver...)
Driver version = 7.5.000.06, ILibrary version = 7.5.004.00, IServer version = 7.5.016.00, DTD version = 4.0, Active calls = 1, Outstanding request id's = 0
02/06/09 13:06:58.061 XM|00000004|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  Sent    on socket <IVR_mpsbuc14:7100:IP[XXX.XX.XX.XX]> XML message <<?xml version="1.0" encoding="iso-8859-1"?><!DOCTYPE GctiMsg SYSTEM "IServer.dtd"><GctiMsg><CallId>IVR_mpsbuc14�20�2</CallId><NewCall CallControlMode="Network" Version="4.0"><CalledNum>20</CalledNum></NewCall></GctiMsg>>
02/06/09 13:06:58.061 IS<00000004|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  NewCall Call ID = " 5000", DNIS = "", ANI = "", CDT Tag = ""
02/06/09 13:06:58.061 AP<00000004|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  NoteCallStart rc=0
02/06/09 13:06:58.070 AP>ffffffff|IVR_mpsbuc14:::::                                    Timeout value changed from 5000 to 50
02/06/09 13:06:58.070 AP>00000004|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply request id = 00000004
02/06/09 13:06:58.071 AP<00000004|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply "OK"
02/06/09 13:06:58.080 AP>00000005|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetCallInfo Type = "DNIS" with Call State = "Unknown"
02/06/09 13:06:58.080 AP<00000005|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetCallInfo rc=0
02/06/09 13:06:58.090 AP>00000005|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply request id = 00000005
02/06/09 13:06:58.090 AP<00000005|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply "NULL"
02/06/09 13:06:58.100 AP>00000006|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetCallInfo Type = "ANI" with Call State = "Unknown"
02/06/09 13:06:58.100 AP<00000006|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetCallInfo rc=0
02/06/09 13:06:58.110 IS<ffffffff|IVR_mpsbuc14:::IP[XXX.XX.XX.XX]:7100:                    ilLocalPrnSelector input string is 82 bytes
02/06/09 13:06:58.110 AP>00000006|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply request id = 00000006
02/06/09 13:06:58.110 AP<00000006|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply "NULL"
02/06/09 13:06:58.110 IS>ffffffff|IVR_mpsbuc14:::IP[XXX.XX.XX.XX]:7100:                    KeepAlive response.
(...snipp from ivr_driver...)
[/code]

the call function GetReply are all NULL.


[code]
(...snipp from TServerIVR...)
13:09:28.618 Trc 04541 Message EventRinging received from 65201 ( 'buc_tserver_p')
@13:09:28.6181 [0] message EventRinging
        AttributeCallType      2
        AttributeCallID 18091693
        AttributeConnID 006c01a5446f9c07
        AttributeCallUUID      '005E0236-1A68-198C-A640-AC103133AA77'
        AttributeANI    '[MY_PHONE_NUMBER]'
        AttributeThisDN '898719'
        AttributeThisDNRole    2
        AttributeThisTrunk      2055
        AttributeOtherTrunk    10448
        AttributeOtherDN        '[MY_PHONE_NUMBER]'
        AttributeOtherDNRole    1
        AttributeCallState      0
        AttributeTimeinSecs    1233918568 (13:09:28)
        AttributeTimeinuSecs    616758
        AttributeEventSequenceNumber    000000000b2e5a38
13:09:28.620 Trc 04541 Message EventAttachedDataChanged received from 65201 ( 'buc_tserver_p')
@13:09:28.6203 [0] message EventAttachedDataChanged
        AttributeCallType      2
        AttributeCallID 18091693
        AttributeConnID 006c01a5446f9c07
        AttributeCallUUID      '005E0236-1A68-198C-A640-AC103133AA77'
        AttributeUserData      [64] 00 03 00 00..
                'k_ani' '0[MY_PHONE_NUMBER]'
                'k_home_location'      'buc'
                'k_from_ivr'    'true'
        AttributeANI    '[MY_PHONE_NUMBER]'
        AttributeThisDN '898719'
        AttributeThisDNRole    2
        AttributeThirdPartyDN  '898719'
        AttributeTimeinSecs    1233918568 (13:09:28)
        AttributeTimeinuSecs    619024
        AttributeEventSequenceNumber    000000000b2e5a39
@13:09:29.7850 [gli:WARN]: request for fd: 17
@13:09:29.7851 [gli:DEBUG]: Receiving message on ( -1 , 1 )

        fd = 17
        localAddr = IP[XXX.XX.XX.XX]:7100
        remoteAddr = IP[YYY.YY.YY.YYY]:51190
@13:09:29.7853 [gli:DEBUG3]: Read:
    0:  00 03 00 dd 02 00 3c 3f 78 6d 6c 20 76 65 72 73 * ......<?xml vers
  16:  69 6f 6e 3d 22 31 2e 30 22 20 65 6e 63 6f 64 69 * ion="1.0" encodi
  32:  6e 67 3d 22 69 73 6f 2d 38 38 35 39 2d 31 22 3f * ng="iso-8859-1"?
  48:  3e 3c 21 44 4f 43 54 59 50 45 20 47 63 74 69 4d * ><!DOCTYPE GctiM
  64:  73 67 20 53 59 53 54 45 4d 20 22 49 53 65 72 76 * sg SYSTEM "IServ
  80:  65 72 2e 64 74 64 22 3e 3c 47 63 74 69 4d 73 67 * er.dtd"><GctiMsg
  96:  3e 3c 43 61 6c 6c 49 64 3e 49 56 52 5f 6d 70 73 * ><CallId>IVR_mps
  112:  62 75 63 31 34 ff 32 30 ff 32 3c 2f 43 61 6c 6c * buc14.20.2</Call
  128:  49 64 3e 3c 4e 65 77 43 61 6c 6c 20 43 61 6c 6c * Id><NewCall Call
  144:  43 6f 6e 74 72 6f 6c 4d 6f 64 65 3d 22 4e 65 74 * ControlMode="Net
  160:  77 6f 72 6b 22 20 56 65 72 73 69 6f 6e 3d 22 34 * work" Version="4
  176:  2e 30 22 3e 3c 43 61 6c 6c 65 64 4e 75 6d 3e 32 * .0"><CalledNum>2
  192:  30 3c 2f 43 61 6c 6c 65 64 4e 75 6d 3e 3c 2f 4e * 0</CalledNum></N
  208:  65 77 43 61 6c 6c 3e 3c 2f 47 63 74 69 4d 73 67 * ewCall></GctiMsg
  224:  3e                                              * >
@13:09:29.7855 [xml:DEBUG]: XmlSap::process(): Xml string received = [ <?xml version="1.0" encoding="iso-8859-1"?><!DOCTYPE GctiMsg
SYSTEM "IServer.dtd"><GctiMsg><CallId>IVR_mpsbuc14˙20˙2</CallId><NewCall CallControlMode="Network" Version="4.0"><CalledNum>20</Call
edNum></NewCall></GctiMsg> ]
@13:09:29.7929 [tcl:DEBUG2]: App Received:    Type = Indication
  Id = "00.00.00.00.00.00.01.2e"
  Call Id = "00.00.00.00.00.00.00.2f"
  Data = ...
  Offset = 6
  Properties =
        [GLI] = Properties:
              [AppId] = Int(0)
              [Circuit] = Int(1)
              [Group] = Int(-1)
              [Version] = Int(2)
        [XML] = Properties:
              [Encoding] = String(iso-8859-1)
              [Message] = Properties:
                  [GctiMsg] = Properties:
                        [CallId] = Properties:
                            [Val] = String(IVR_mpsbuc14˙20˙2)
                        [NewCall] = Properties:
                            [Attrs] = Properties:
                                  [CallControlMode] = String(Network)
                                  [Version] = String(4.0)
                            [CalledNum] = Properties:
                                  [Val] = String(20)
              [Version] = String(1.0)

13:09:29.793 Trc 29043 Received message 00.00.00.00.00.00.00.2f:00.00.00.00.00.00.01.2e:New Call Network.
@13:09:29.7935 [tcl:DEBUG2]: TimerManager::startTimer: local id: 0 , conn id: 127926275 , period: 28800000
@13:09:29.7945 [tcl:DEBUG]: TclHandler::copy_value : IN_MSG [ GLI.Group ] -> USER_DATA [ GLI.Group ]
@13:09:29.7946 [tcl:DEBUG]: TclHandler::copy_value : IN_MSG [ GLI.Circuit ] -> USER_DATA [ GLI.Circuit ]
@13:09:29.7948 [tcl:DEBUG]: TclHandler::get_value : IN_MSG [ XML.Message.GctiMsg.NewCall.CalledNum.Val ] = String(20)
@13:09:29.7949 [tcl:DEBUG]: TclHandler::get_value : IN_MSG [ XML.Message.GctiMsg.NewCall.Attrs.Version ] = String(4.0)
@13:09:29.7950 [tcl:DEBUG]: TclHandler::get_value : IN_MSG [ XML.Message.GctiMsg.NewCall.ANI.Val ]: set to default val:
@13:09:29.7951 [tcl:DEBUG]: TclHandler::get_value : IN_MSG [ XML.Message.GctiMsg.NewCall.DNIS.Val ]: set to default val:
@13:09:29.7957 [tcl:DEBUG]: TclHandler::value_exists : ENV_DATA [ TLIB.DNList.20 ] does not exist
@13:09:29.7958 [tcl:DEBUG]: TclHandler::get_value : IN_MSG [ GLI.Group ] = Int(-1)
@13:09:29.7958 [tcl:DEBUG]: TclHandler::get_value : IN_MSG [ GLI.Circuit ] = Int(1)
@13:09:29.7960 [tcl:DEBUG]: TclHandler::set_value : USER_DATA [ INFO.PortDN ] = String(898719)
@13:09:29.7961 [tcl:DEBUG]: TclHandler::set_value : USER_DATA [ TSClient ] = String(TServer_IVR_750_buc)
@13:09:29.7962 [tcl:DEBUG]: TclHandler::set_value : USER_DATA [ ThisDN ] = String(898719)
@13:09:29.7962 [tcl:DEBUG]: TclHandler::set_value : USER_DATA [ RouteDN ] = String(898719)
@13:09:29.7963 [tcl:DEBUG]: TclHandler::set_value : USER_DATA [ IVROpMode ] = Int(1)
@13:09:29.7965 [tcl:DEBUG]: TclHandler::get_value : USER_DATA [ IVROpMode ] = Int(1)
@13:09:29.7966 [tcl:DEBUG]: TclHandler::get_value : ENV_DATA [ GLM.LicensedForIVRBehind ] = Bool(true)
@13:09:29.7968 [tcl:DEBUG]: TclHandler::value_exists : USER_DATA [ Licensed ] does not exist
@13:09:29.7969 [tcl:DEBUG]: TclHandler::get_value : ENV_DATA [ GLM.IVR.ActiveBehindCalls ] = Int(0)
@13:09:29.7969 [tcl:DEBUG]: TclHandler::set_value : ENV_DATA [ GLM.IVR.ActiveBehindCalls ] = Int(1)
@13:09:29.7970 [tcl:DEBUG]: TclHandler::get_value : ENV_DATA [ GLM.IVR.MaxBehindCallsForInterval ] = Int(0)
@13:09:29.7970 [tcl:DEBUG]: TclHandler::set_value : ENV_DATA [ GLM.IVR.MaxBehindCallsForInterval ] = Int(1)
@13:09:29.7971 [tcl:DEBUG]: TclHandler::set_value : USER_DATA [ Licensed ] = Bool(true)
@13:09:29.7971 [tcl:DEBUG]: TclHandler::get_value : IN_MSG [ XML.Encoding ] = String(iso-8859-1)
@13:09:29.7972 [tcl:DEBUG]: TclHandler::set_value : USER_DATA [ DestEncoder ] = String(ISO-8859-1)
@13:09:29.7973 [tcl:DEBUG]: TclHandler::copy_value : IN_MSG [ XML.Message.GctiMsg.CallId.Val ] -> USER_DATA [ CallID ]
@13:09:29.7974 [tcl:DEBUG]: TclHandler::get_value : GLOBAL_DATA [ FlowControl ] = Bool(false)
@13:09:29.7976 [tcl:DEBUG]: TclHandler::create_msg : Created message: ( 00.00.00.00.00.00.00.2f 00.00.00.00.00.00.01.2f )
@13:09:29.7976 [tcl:DEBUG]: TclHandler::set_value : OUT_MSG [ Type ] = String(NewCall)
@13:09:29.7977 [tcl:DEBUG]: TclHandler::copy_value : USER_DATA [ TSClient ] -> OUT_MSG [ ClientName ]
@13:09:29.7978 [tcl:DEBUG]: TclHandler::copy_value : USER_DATA [ ThisDN ] -> OUT_MSG [ DN ]
13:09:29.797 Trc 29044 Sent message 00.00.00.00.00.00.00.2f:00.00.00.00.00.00.01.2f:NewCall.
(...snipp from TServerIVR...)
[/code]

And all the libraries loaded in the TServerIVR:

[code]
17:41:02.687 Trc 29011 Loaded config file I-Server.smx. Type: SMX. Version: 2192. Description: IVR Server:7.5.016.00.
17:41:03.160 Trc 29021 SAP(./xmlSap_64.sl) loaded.
17:41:03.173 Trc 29021 SAP(./gliSap_64.sl) loaded.
17:41:03.248 Trc 29021 SAP(./tserverClientSap_64.sl) loaded.
17:41:03.266 Trc 29021 SAP(./cmeSap_64.sl) loaded.
17:41:03.271 Trc 29021 SAP(./iserverGLMSap_64.sl) loaded.
17:41:03.364 Trc 29021 SAP(./tclSmAppSap_64.sl) loaded.
....
17:41:04.809 Trc 29021 SAP(./callIdSap_64.sl) loaded.
@17:41:04.8097 [nts:DEBUG]: SharedLib::open Unable to load: ./tserverSap , reason: No such file or directory
17:41:04.819 Trc 29021 SAP(./tserverSap_64.sl) loaded.
@17:41:04.8203 [nts:DEBUG]: SharedLib::open Unable to load: ./statSap , reason: No such file or directory
17:41:04.842 Trc 29021 SAP(./statSap_64.sl) loaded.
[/code]

As I can see the TServer sends request to the IVRTServer but the TServerIVR call keys (ANI and DNIS) are not available are not available even though the values are passed by the (main)Tserver throw the MessageServer, where is the problem here?

Can someone share some light on me?

Regards

[René]

Hi,

Snippet of posted TServerIVR covers only first request received from IVR driver where IVR driver reports a new call. Another requests (GetCallInfo) from driver isn't there. Could you please post here TServerIVR showing the GetCallInfo requests.

R.

[bogdan]

This all I have from a trace ... it seems the GetCallInfo is not here

[code]
@13:09:28.6181 [0] message EventRinging
AttributeCallType 2
AttributeCallID 18091693
AttributeConnID 006c01a5446f9c07
AttributeCallUUID '005E0236-1A68-198C-A640-AC103133AA77'
AttributeANI '[MYPHONENUMBER]'
AttributeThisDN '898719'
AttributeThisDNRole 2
AttributeThisTrunk 2055
AttributeOtherTrunk 10448
AttributeOtherDN '[MYPHONENUMBER]'
AttributeOtherDNRole 1
AttributeCallState 0
AttributeTimeinSecs 1233918568 (13:09:28)
AttributeTimeinuSecs 616758
AttributeEventSequenceNumber 000000000b2e5a38
13:09:28.620 Trc 04541 Message EventAttachedDataChanged received from 65201 ( 'buc_tserver_p')
@13:09:28.6203 [0] message EventAttachedDataChanged
AttributeCallType 2
AttributeCallID 18091693
AttributeConnID 006c01a5446f9c07
AttributeCallUUID '005E0236-1A68-198C-A640-AC103133AA77'
AttributeUserData [64] 00 03 00 00..
'k_ani' '0[MYPHONENUMBER]'
'k_home_location' 'buc'
'k_from_ivr' 'true'
AttributeANI '[MYPHONENUMBER]'
AttributeThisDN '898719'
AttributeThisDNRole 2
AttributeThirdPartyDN '898719'
AttributeTimeinSecs 1233918568 (13:09:28)
AttributeTimeinuSecs 619024
AttributeEventSequenceNumber 000000000b2e5a39
@13:09:29.7850 [gli:WARN]: request for fd: 17
@13:09:29.7851 [gli:DEBUG]: Receiving message on ( -1 , 1 )
fd = 17
localAddr = IP[XXX.XX.XX.XX]:7100
remoteAddr = IP[YYY.YY.YY.YYY]:51190
@13:09:29.7853 [gli:DEBUG3]: Read:
    0:  00 03 00 dd 02 00 3c 3f 78 6d 6c 20 76 65 72 73 * ......<?xml vers
  16:  69 6f 6e 3d 22 31 2e 30 22 20 65 6e 63 6f 64 69 * ion="1.0" encodi
  32:  6e 67 3d 22 69 73 6f 2d 38 38 35 39 2d 31 22 3f * ng="iso-8859-1"?
  48:  3e 3c 21 44 4f 43 54 59 50 45 20 47 63 74 69 4d * ><!DOCTYPE GctiM
  64:  73 67 20 53 59 53 54 45 4d 20 22 49 53 65 72 76 * sg SYSTEM "IServ
  80:  65 72 2e 64 74 64 22 3e 3c 47 63 74 69 4d 73 67 * er.dtd"><GctiMsg
  96:  3e 3c 43 61 6c 6c 49 64 3e 49 56 52 5f 6d 70 73 * ><CallId>IVR_mps
  112:  62 75 63 31 34 ff 32 30 ff 32 3c 2f 43 61 6c 6c * buc14.20.2</Call
  128:  49 64 3e 3c 4e 65 77 43 61 6c 6c 20 43 61 6c 6c * Id><NewCall Call
  144:  43 6f 6e 74 72 6f 6c 4d 6f 64 65 3d 22 4e 65 74 * ControlMode="Net
  160:  77 6f 72 6b 22 20 56 65 72 73 69 6f 6e 3d 22 34 * work" Version="4
  176:  2e 30 22 3e 3c 43 61 6c 6c 65 64 4e 75 6d 3e 32 * .0"><CalledNum>2
  192:  30 3c 2f 43 61 6c 6c 65 64 4e 75 6d 3e 3c 2f 4e * 0</CalledNum></N
  208:  65 77 43 61 6c 6c 3e 3c 2f 47 63 74 69 4d 73 67 * ewCall></GctiMsg
  224:  3e                                              * >
@13:09:29.7855 [xml:DEBUG]: XmlSap::process(): Xml string received = [ <?xml version="1.0" encoding="iso-8859-1"?><!DOCTYPE GctiMsg SYSTEM "IServer.dtd"><GctiMsg><CallId>IVR_mpsbuc14˙20˙2</CallId><NewCall CallControlMode="Network" Version="4.0"><CalledNum>20</CalledNum></NewCall></GctiMsg> ]
@13:09:29.7929 [tcl:DEBUG2]: App Received:    Type = Indication
  Id = "00.00.00.00.00.00.01.2e"
  Call Id = "00.00.00.00.00.00.00.2f"
  Data = ...
  Offset = 6
  Properties =
        [GLI] = Properties:
              [AppId] = Int(0)
              [Circuit] = Int(1)
              [Group] = Int(-1)
              [Version] = Int(2)
        [XML] = Properties:
              [Encoding] = String(iso-8859-1)
              [Message] = Properties:
                  [GctiMsg] = Properties:
                        [CallId] = Properties:
                            [Val] = String(IVR_mpsbuc14˙20˙2)
                        [NewCall] = Properties:
                            [Attrs] = Properties:
                                  [CallControlMode] = String(Network)
                                  [Version] = String(4.0)
                            [CalledNum] = Properties:
                                  [Val] = String(20)
              [Version] = String(1.0)

13:09:29.793 Trc 29043 Received message 00.00.00.00.00.00.00.2f:00.00.00.00.00.00.01.2e:New Call Network.
@13:09:29.7935 [tcl:DEBUG2]: TimerManager::startTimer: local id: 0 , conn id: 127926275 , period: 28800000
@13:09:29.7945 [tcl:DEBUG]: TclHandler::copy_value : IN_MSG [ GLI.Group ] -> USER_DATA [ GLI.Group ]
@13:09:29.7946 [tcl:DEBUG]: TclHandler::copy_value : IN_MSG [ GLI.Circuit ] -> USER_DATA [ GLI.Circuit ]
@13:09:29.7948 [tcl:DEBUG]: TclHandler::get_value : IN_MSG [ XML.Message.GctiMsg.NewCall.CalledNum.Val ] = String(20)
@13:09:29.7949 [tcl:DEBUG]: TclHandler::get_value : IN_MSG [ XML.Message.GctiMsg.NewCall.Attrs.Version ] = String(4.0)
@13:09:29.7950 [tcl:DEBUG]: TclHandler::get_value : IN_MSG [ XML.Message.GctiMsg.NewCall.ANI.Val ]: set to default val:
@13:09:29.7951 [tcl:DEBUG]: TclHandler::get_value : IN_MSG [ XML.Message.GctiMsg.NewCall.DNIS.Val ]: set to default val:
@13:09:29.7957 [tcl:DEBUG]: TclHandler::value_exists : ENV_DATA [ TLIB.DNList.20 ] does not exist
@13:09:29.7958 [tcl:DEBUG]: TclHandler::get_value : IN_MSG [ GLI.Group ] = Int(-1)
@13:09:29.7958 [tcl:DEBUG]: TclHandler::get_value : IN_MSG [ GLI.Circuit ] = Int(1)
@13:09:29.7960 [tcl:DEBUG]: TclHandler::set_value : USER_DATA [ INFO.PortDN ] = String(898719)
@13:09:29.7961 [tcl:DEBUG]: TclHandler::set_value : USER_DATA [ TSClient ] = String(TServer_IVR_750_buc)
@13:09:29.7962 [tcl:DEBUG]: TclHandler::set_value : USER_DATA [ ThisDN ] = String(898719)
@13:09:29.7962 [tcl:DEBUG]: TclHandler::set_value : USER_DATA [ RouteDN ] = String(898719)
@13:09:29.7963 [tcl:DEBUG]: TclHandler::set_value : USER_DATA [ IVROpMode ] = Int(1)
@13:09:29.7965 [tcl:DEBUG]: TclHandler::get_value : USER_DATA [ IVROpMode ] = Int(1)
@13:09:29.7966 [tcl:DEBUG]: TclHandler::get_value : ENV_DATA [ GLM.LicensedForIVRBehind ] = Bool(true)
@13:09:29.7968 [tcl:DEBUG]: TclHandler::value_exists : USER_DATA [ Licensed ] does not exist
@13:09:29.7969 [tcl:DEBUG]: TclHandler::get_value : ENV_DATA [ GLM.IVR.ActiveBehindCalls ] = Int(0)
@13:09:29.7969 [tcl:DEBUG]: TclHandler::set_value : ENV_DATA [ GLM.IVR.ActiveBehindCalls ] = Int(1)
@13:09:29.7970 [tcl:DEBUG]: TclHandler::get_value : ENV_DATA [ GLM.IVR.MaxBehindCallsForInterval ] = Int(0)
@13:09:29.7970 [tcl:DEBUG]: TclHandler::set_value : ENV_DATA [ GLM.IVR.MaxBehindCallsForInterval ] = Int(1)
@13:09:29.7971 [tcl:DEBUG]: TclHandler::set_value : USER_DATA [ Licensed ] = Bool(true)
@13:09:29.7971 [tcl:DEBUG]: TclHandler::get_value : IN_MSG [ XML.Encoding ] = String(iso-8859-1)
@13:09:29.7972 [tcl:DEBUG]: TclHandler::set_value : USER_DATA [ DestEncoder ] = String(ISO-8859-1)
@13:09:29.7973 [tcl:DEBUG]: TclHandler::copy_value : IN_MSG [ XML.Message.GctiMsg.CallId.Val ] -> USER_DATA [ CallID ]
@13:09:29.7974 [tcl:DEBUG]: TclHandler::get_value : GLOBAL_DATA [ FlowControl ] = Bool(false)
@13:09:29.7976 [tcl:DEBUG]: TclHandler::create_msg : Created message: ( 00.00.00.00.00.00.00.2f 00.00.00.00.00.00.01.2f )
@13:09:29.7976 [tcl:DEBUG]: TclHandler::set_value : OUT_MSG [ Type ] = String(NewCall)
@13:09:29.7977 [tcl:DEBUG]: TclHandler::copy_value : USER_DATA [ TSClient ] -> OUT_MSG [ ClientName ]
@13:09:29.7978 [tcl:DEBUG]: TclHandler::copy_value : USER_DATA [ ThisDN ] -> OUT_MSG [ DN ]
13:09:29.797 Trc 29044 Sent message 00.00.00.00.00.00.00.2f:00.00.00.00.00.00.01.2f:NewCall.
@13:09:29.7980 [tcl:DEBUG2]: App Sent:    Type = Notify
  Id = "00.00.00.00.00.00.01.2f"
  Call Id = "00.00.00.00.00.00.00.2f"
  Data = ...
  Offset = 0
  Properties =
        [ClientName] = String(TServer_IVR_750_buc)
        [DN] = String(898719)
        [Type] = String(NewCall)

@13:09:29.7981 [tcl:DEBUG]: TclHandler::timer : cmd: timer_start timerName: wait-for-ringing
@13:09:29.7981 [tcl:DEBUG2]: TimerManager::startTimer: local id: 1 , conn id: 117440538 , period: 60000
@13:09:29.7982 [tcl:DEBUG]: TclHandler::set_condition : add blocking condition = Established
@13:09:29.7983 [tcl:DEBUG]: TclHandler::set_condition : add blocking condition = Ringing
@13:09:29.7983 [tcl:DEBUG]: TclHandler::set_condition : add non-blocking condition = Party Changed
@13:09:29.7984 [tcl:DEBUG]: TclHandler::get_value : USER_DATA [ ThisDN ] = String(898719)
@13:09:29.7984 [tcl:DEBUG]: TclHandler::set_value : USER_DATA [ CallType ] = Int(2)
@13:09:29.7985 [tcl:DEBUG]: TclHandler::copy_value : IN_MSG [ XML.Message.GctiMsg.NewCall.CalledNum.Val ] -> USER_DATA [ INFO.CalledNum ]
@13:09:29.7986 [tcl:DEBUG]: TclHandler::copy_value : IN_MSG [ XML.Message.GctiMsg.NewCall.ANI.Val ] does not exist
@13:09:29.7986 [tcl:DEBUG]: TclHandler::copy_value : IN_MSG [ XML.Message.GctiMsg.NewCall.DNIS.Val ] does not exist
@13:09:29.7989 [tcl:DEBUG]: TclHandler::sub_call : created sub call for call id: 00.00.00.00.00.00.00.2f
@13:09:29.7990 [tcl:DEBUG]: TclHandler::sub_call : created sub call for call id: 00.00.00.00.00.00.00.2f
@13:09:29.7991 [tcl:DEBUG]: TclHandler::sub_call : created sub call for call id: 00.00.00.00.00.00.00.2f
@13:09:29.7993 [tcl:DEBUG]: TclHandler::erase_value : USER_DATA [ MultipleParty ]
@13:09:29.7994 [tcl:DEBUG]: TclHandler::sub_call : created sub call for call id: 00.00.00.00.00.00.00.2f
@13:09:29.7995 [tcl:DEBUG]: TclHandler::sub_call : created sub call for call id: 00.00.00.00.00.00.00.2f
@13:09:29.7996 [tcl:DEBUG]: TclHandler::value_exists : USER_DATA [ RoutingStarted ] does not exist
@13:09:29.7997 [tcl:DEBUG]: TclHandler::get_value : USER_DATA [ IVROpMode ] = Int(1)
@13:09:29.7998 [tcl:DEBUG]: TclHandler::set_condition : add non-blocking condition = Call Info
@13:09:29.7998 [tcl:DEBUG]: TclHandler::set_condition : add non-blocking condition = Log Message
@13:09:29.7998 [tcl:DEBUG]: TclHandler::set_value : USER_DATA [ Version ] = String(4.0)
@13:09:29.8337 [gli:WARN]: request for fd: 17
@13:09:29.8338 [gli:DEBUG]: Receiving message on ( -1 , 1 )
fd = 17
localAddr = IP[XXX.XX.XX.XX]:7100
remoteAddr = IP[YYY.YY.YY.YYY]:51190
@13:09:29.8338 [gli:DEBUG3]: Read:
    0:  00 00 00 02 02 00                              * ......
@13:09:29.8339 [gli:DEBUG]: Sending message on ( -1 , 1 )
fd = 17
localAddr = IP[XXX.XX.XX.XX]:7100
remoteAddr = IP[YYY.YY.YY.YYY]:51190
@13:09:29.8339 [gli:DEBUG3]: Wrote:
    0:  00 01 00 02 02 00                              * ......
13:09:29.926 Trc 04541 Message EventOffHook received from 65201 ( 'buc_tserver_p')
@13:09:29.9267 [0] message EventOffHook
AttributeThisDN '898719'
AttributeTimeinSecs 1233918569 (13:09:29)
AttributeTimeinuSecs 924814
AttributeEventSequenceNumber 000000000b2e5a4a
13:09:29.927 Trc 04541 Message EventEstablished received from 65201 ( 'buc_tserver_p')
@13:09:29.9272 [0] message EventEstablished
AttributeCallType 2
AttributeCallID 18091693
AttributeConnID 006c01a5446f9c07
AttributeCallUUID '005E0236-1A68-198C-A640-AC103133AA77'
AttributeUserData [64] 00 03 00 00..
'k_ani' '0[MYPHONENUMBER]'
'k_home_location' 'buc'
'k_from_ivr' 'true'
AttributeANI '[MYPHONENUMBER]'
AttributeThisDN '898719'
AttributeThisDNRole 2
AttributeThisTrunk 2055
AttributeOtherTrunk 10448
AttributeOtherDNRole 1
AttributeOtherDN '[MYPHONENUMBER]'
AttributeCallState 0
AttributeTimeinSecs 1233918569 (13:09:29)
AttributeTimeinuSecs 925295
AttributeEventSequenceNumber 000000000b2e5a4b
@13:09:29.9274 [tcl:DEBUG2]: App Received:    Type = Indication
  Id = "00.00.00.00.00.00.01.30"
  Call Id = "00.00.00.00.00.00.00.18"
  Data = ...
  Offset = 0
  Properties =
        [TLIB] = Properties:
              [ClientName] = String(buc_tserver_p)
              [Message] = Properties:
                  [AttributeEventSequenceNumber] = OctetString("00.00.00.00.0b.2e.5a.4a")
                  [AttributeThisDN] = String(898719)
                  [AttributeTimeinSecs] = Int(1233918569)
                  [AttributeTimeinuSecs] = Int(924814)
                  [Id] = String(EventOffHook)

13:09:29.927 Trc 29043 Received message 00.00.00.00.00.00.00.18:00.00.00.00.00.00.01.30:Off Hook.
@13:09:29.9281 [tcl:DEBUG]: TclHandler::set_condition : add non-blocking condition = Ignorable
@13:09:29.9742 [gli:WARN]: request for fd: 17
@13:09:29.9743 [gli:DEBUG]: Receiving message on ( -1 , 1 )
fd = 17
localAddr = IP[XXX.XX.XX.XX]:7100
remoteAddr = IP[YYY.YY.YY.YYY]:51190
@13:09:29.9744 [gli:DEBUG3]: Read:
    0:  00 03 00 f9 02 00 3c 3f 78 6d 6c 20 76 65 72 73 * ......<?xml vers
  16:  69 6f 6e 3d 22 31 2e 30 22 20 65 6e 63 6f 64 69 * ion="1.0" encodi
  32:  6e 67 3d 22 69 73 6f 2d 38 38 35 39 2d 31 22 3f * ng="iso-8859-1"?
  48:  3e 3c 21 44 4f 43 54 59 50 45 20 47 63 74 69 4d * ><!DOCTYPE GctiM
  64:  73 67 20 53 59 53 54 45 4d 20 22 49 53 65 72 76 * sg SYSTEM "IServ
  80:  65 72 2e 64 74 64 22 3e 3c 47 63 74 69 4d 73 67 * er.dtd"><GctiMsg
  96:  3e 3c 43 61 6c 6c 49 64 3e 49 56 52 5f 6d 70 73 * ><CallId>IVR_mps
  112:  62 75 63 31 34 ff 32 30 ff 32 3c 2f 43 61 6c 6c * buc14.20.2</Call
  128:  49 64 3e 3c 45 6e 64 43 61 6c 6c 20 45 6e 64 43 * Id><EndCall EndC
  144:  61 75 73 65 3d 22 4e 6f 72 6d 61 6c 22 3e 3c 45 * ause="Normal"><E
  160:  78 74 6e 73 45 78 3e 3c 4e 6f 64 65 20 4e 61 6d * xtnsEx><Node Nam
  176:  65 3d 22 47 43 54 49 41 63 74 69 76 65 52 65 6c * e="GCTIActiveRel
  192:  65 61 73 65 22 20 54 79 70 65 3d 22 53 74 72 22 * ease" Type="Str"
  208:  20 56 61 6c 3d 22 66 61 6c 73 65 22 20 2f 3e 3c *  Val="false" /><
  224:  2f 45 78 74 6e 73 45 78 3e 3c 2f 45 6e 64 43 61 * /ExtnsEx></EndCa
  240:  6c 6c 3e 3c 2f 47 63 74 69 4d 73 67 3e          * ll></GctiMsg>
@13:09:29.9746 [xml:DEBUG]: XmlSap::process(): Xml string received = [ <?xml version="1.0" encoding="iso-8859-1"?><!DOCTYPE GctiMsg SYSTEM "IServer.dtd"><GctiMsg><CallId>IVR_mpsbuc14˙20˙2</CallId><EndCall EndCause="Normal"><ExtnsEx><Node Name="GCTIActiveRelease" Type="Str" Val="false" /></ExtnsEx></EndCall></GctiMsg> ]
@13:09:29.9820 [tcl:DEBUG2]: App Received:    Type = Indication
  Id = "00.00.00.00.00.00.01.31"
  Call Id = "00.00.00.00.00.00.00.2f"
  Data = ...
  Offset = 6
  Properties =
        [GLI] = Properties:
              [AppId] = Int(0)
              [Circuit] = Int(1)
              [Group] = Int(-1)
              [Version] = Int(2)
        [XML] = Properties:
              [Encoding] = String(iso-8859-1)
              [Message] = Properties:
                  [GctiMsg] = Properties:
                        [CallId] = Properties:
                            [Val] = String(IVR_mpsbuc14˙20˙2)
                        [EndCall] = Properties:
                            [Attrs] = Properties:
                                  [EndCause] = String(Normal)
                            [ExtnsEx] = Properties:
                                  [GCTIActiveRelease] = Properties:
                                      [Attrs] = Properties:
                                            [Name] = String(GCTIActiveRelease)
                                            [Type] = String(Str)
                                            [Val] = String(false)
                                      [Tag] = String(Node)
              [Version] = String(1.0)

13:09:29.982 Trc 29043 Received message 00.00.00.00.00.00.00.2f:00.00.00.00.00.00.01.31:End Call.
@13:09:29.9823 [tcl:DEBUG]: TclGuard( Not IVR Network )::eval result: true
@13:09:29.9825 [tcl:DEBUG]: TclHandler::get_event_name : event: End Call
@13:09:29.9828 [tcl:DEBUG]: TclHandler::queue_event  creating internal event: InternalStopIServer ( 00.00.00.00.00.00.00.2f (null) )
@13:09:29.9829 [tcl:DEBUG]: TclHandler::queue_event  creating internal event: InternalStopStat ( 00.00.00.00.00.00.00.2f (null) )
@13:09:29.9830 [tcl:DEBUG]: TclHandler::queue_event  creating internal event: InternalStopUData ( 00.00.00.00.00.00.00.2f (null) )
@13:09:29.9831 [tcl:DEBUG]: TclHandler::queue_event  creating internal event: InternalStopConsult ( 00.00.00.00.00.00.00.2f (null) )
@13:09:29.9832 [tcl:DEBUG]: TclHandler::queue_event  creating internal event: InternalStopAccessNum ( 00.00.00.00.00.00.00.2f (null) )
@13:09:29.9833 [tcl:DEBUG]: TclHandler::queue_event  creating internal event: InternalStopRoute ( 00.00.00.00.00.00.00.2f (null) )
@13:09:29.9838 [tcl:DEBUG]: TclHandler::copy_value : IN_MSG [ GLI.Group ] -> USER_DATA [ GLI.Group ]
@13:09:29.9838 [tcl:DEBUG]: TclHandler::copy_value : IN_MSG [ GLI.Circuit ] -> USER_DATA [ GLI.Circuit ]
@13:09:29.9841 [tcl:DEBUG]: TclHandler::value_exists : IN_MSG [ XML.Message.GctiMsg.EndCall.UserData ] does not exist
@13:09:29.9842 [tcl:DEBUG]: TclHandler::value_exists : IN_MSG [ XML.Message.GctiMsg.EndCall.Extensions ] does not exist
@13:09:29.9843 [tcl:DEBUG]: TclHandler::value_exists : IN_MSG [ XML.Message.GctiMsg.EndCall.ExtnsEx ] exists
@13:09:29.9844 [tcl:DEBUG]: TclHandler::value_exists : IN_MSG [ XML.Message.GctiMsg.EndCall.UDataEx ] does not exist
@13:09:29.9845 [tcl:DEBUG]: TclHandler::value_exists : IN_MSG [ XML.Message.GctiMsg.EndCall.ExtnsEx ] exists
@13:09:29.9846 [tcl:DEBUG]: TclHandler::value_type : IN_MSG [ XML.Message.GctiMsg.EndCall.ExtnsEx ]: type: PM
@13:09:29.9849 [tcl:DEBUG]: TclHandler::value_exists : IN_MSG [ XML.Message.GctiMsg.EndCall.ExtnsEx.GCTIActiveRelease ] exists
@13:09:29.9850 [tcl:DEBUG]: TclHandler::value_type : IN_MSG [ XML.Message.GctiMsg.EndCall.ExtnsEx.GCTIActiveRelease ]: type: PM
@13:09:29.9852 [tcl:DEBUG]: TclHandler::get_value : IN_MSG [ XML.Message.GctiMsg.EndCall.ExtnsEx.GCTIActiveRelease.Attrs.Name ] = String(GCTIActiveRelease)
@13:09:29.9854 [tcl:DEBUG]: TclHandler::get_value : IN_MSG [ XML.Message.GctiMsg.EndCall.ExtnsEx.GCTIActiveRelease.Attrs.Type ] = String(Str)
@13:09:29.9855 [tcl:DEBUG]: TclHandler::get_value : IN_MSG [ XML.Message.GctiMsg.EndCall.ExtnsEx.GCTIActiveRelease.Attrs.Val ] = String(false)
@13:09:29.9856 [tcl:DEBUG]: TclHandler::set_value : USER_DATA [ Temp.Extensions.GCTIActiveRelease ] = String(false)
@13:09:29.9862 [tcl:DEBUG]: TclHandler::value_exists : USER_DATA [ Temp.UData ] does not exist
@13:09:29.9863 [tcl:DEBUG]: TclHandler::get_config_info [ IServer ] . active-release = true
@13:09:29.9863 [tcl:DEBUG]: TclHandler::get_value : USER_DATA [ Temp.Extensions.GCTIActiveRelease ] = String(false)
@13:09:29.9864 [tcl:DEBUG]: TclHandler::value_exists : USER_DATA [ IRProcessing ] does not exist
@13:09:29.9864 [tcl:DEBUG]: TclHandler::value_exists : USER_DATA [ DivertReqd ] does not exist
@13:09:29.9865 [tcl:DEBUG]: TclHandler::get_value : USER_DATA [ IVROpMode ] = Int(1)
@13:09:29.9866 [tcl:DEBUG2]: TimerManager::startTimer: local id: 2 , conn id: 106954777 , period: 30000
@13:09:29.9870 [tcl:DEBUG]: TclHandler::get_event_name : event: InternalStopIServer
@13:09:29.9871 [tcl:DEBUG]: TclHandler::queue_event  creating internal event: InternalStopIServer ( 00.00.00.00.00.00.00.2f (null) )
@13:09:29.9871 [tcl:DEBUG]: TclHandler::is_condition_set : condition: Ringing is set
@13:09:29.9872 [tcl:DEBUG]: TclHandler::update_condition : unblock condition = Ringing
@13:09:29.9880 [tcl:DEBUG]: TclHandler::value_exists : USER_DATA [ SM.LastError.OriginalProps.TLIB.Message ] does not exist
@13:09:29.9881 [tcl:DEBUG]: TclHandler::value_exists : USER_DATA [ SM.LastError.OriginalProps.XML.Message ] does not exist
13:09:35.318 Trc 04541 Message EventReleased received from 65201 ( 'buc_tserver_p')
@13:09:35.3185 [0] message EventReleased
AttributeCallType 2
AttributeCallID 18091693
AttributeConnID 006c01a5446f9c07
AttributeCallUUID '005E0236-1A68-198C-A640-AC103133AA77'
AttributeUserData [64] 00 03 00 00..
'k_ani' '0[MYPHONENUMBER]'
'k_home_location' 'buc'
'k_from_ivr' 'true'
AttributeANI '[MYPHONENUMBER]'
AttributeThisDN '898719'
AttributeThisDNRole 2
AttributeThisTrunk 2055
AttributeOtherTrunk 10448
AttributeOtherDNRole 1
AttributeOtherDN '[MYPHONENUMBER]'
AttributeCallState 0
AttributeTimeinSecs 1233918575 (13:09:35)
AttributeTimeinuSecs 316809
AttributeEventSequenceNumber 000000000b2e5bc9
13:09:35.318 Trc 04541 Message EventOnHook received from 65201 ( 'buc_tserver_p')
@13:09:35.3189 [0] message EventOnHook
AttributeThisDN '898719'
AttributeTimeinSecs 1233918575 (13:09:35)
AttributeTimeinuSecs 317299
AttributeEventSequenceNumber 000000000b2e5bca
@13:09:35.3192 [tcl:DEBUG2]: App Received:    Type = Indication
  Id = "00.00.00.00.00.00.01.32"
  Call Id = "00.00.00.00.00.00.00.18"
  Data = ...
  Offset = 0
  Properties =
        [TLIB] = Properties:
              [ClientName] = String(buc_tserver_p)
              [Message] = Properties:
                  [AttributeEventSequenceNumber] = OctetString("00.00.00.00.0b.2e.5b.ca")
                  [AttributeThisDN] = String(898719)
                  [AttributeTimeinSecs] = Int(1233918575)
                  [AttributeTimeinuSecs] = Int(317299)
                  [Id] = String(EventOnHook)

13:09:35.319 Trc 29043 Received message 00.00.00.00.00.00.00.18:00.00.00.00.00.00.01.32:On Hook.
@13:09:35.3198 [tcl:DEBUG]: TclHandler::set_condition : add non-blocking condition = Ignorable
@13:09:49.8440 [gli:WARN]: request for fd: 17
@13:09:49.8441 [gli:DEBUG]: Receiving message on ( -1 , 1 )
fd = 17
localAddr = IP[XXX.XX.XX.XX]:7100
remoteAddr = IP[YYY.YY.YY.YYY]:51190
@13:09:49.8441 [gli:DEBUG3]: Read:
    0:  00 00 00 02 02 00                              * ......
@13:09:49.8442 [gli:DEBUG]: Sending message on ( -1 , 1 )
fd = 17
localAddr = IP[XXX.XX.XX.XX]:7100
remoteAddr = IP[YYY.YY.YY.YYY]:51190
@13:09:49.8442 [gli:DEBUG3]: Wrote:
    0:  00 01 00 02 02 00                              * ......
@13:09:52.6663 [gli:DEBUG]: Notify Link Status: down
  call: (null)
  local: IP[XXX.XX.XX.XX]:7100
  remote: IP[YYY.YY.YY.YYY]:51190
@13:09:52.6664 [gli:DEBUG]:
  Properties:
          [GLI] = Properties:
              [Circuit] = Int(1)
              [Group] = Int(-1)

@13:09:52.6666 [gli:DEBUG]: closing fd: 17
@13:09:52.6666 [gli:DEBUG]: close group: -1 , circuit: 1 , fd: 17
@13:09:52.6669 [gli:DEBUG]: deleting circuit: 1
@13:09:52.6670 [gli:DEBUG]: del group: -1 , circuit: 1 , fd: -1
@13:09:52.6671 [tcl:DEBUG2]: App Received:    Type = Notify
  Id = "00.00.00.00.00.00.01.33"
  Call Id = (null)
  Data = ...
  Offset = 0
  Properties =
        [GLI] = Properties:
              [Circuit] = Int(1)
              [Group] = Int(-1)
        [LocalAddr] = String(IP[XXX.XX.XX.XX]:7100)
        [RemoteAddr] = String(IP[YYY.YY.YY.YYY]:51190)
        [Source] = String(GLI)
        [Status] = Bool(false)
        [Type] = String(Link Status)

13:09:52.667 Trc 29043 Received message :00.00.00.00.00.00.01.33:GLI Link Down.
@13:09:52.6676 [tcl:DEBUG]: TclHandler::get_value : IN_MSG [ GLI.Group ] = Int(-1)
@13:09:52.6677 [tcl:DEBUG]: TclHandler::get_value : IN_MSG [ GLI.Circuit ] = Int(1)
@13:09:52.6680 [tcl:DEBUG]: TclHandler::create_msg : Created message: ( (null) 00.00.00.00.00.00.01.34 )
@13:09:52.6680 [tcl:DEBUG]: TclHandler::set_value : OUT_MSG [ TLIB.Message.Id ] = String(EventLinkDisconnected)
@13:09:52.6682 [tcl:DEBUG]: TclHandler::set_value : OUT_MSG [ RouteDest ] = String(tserver)
@13:09:52.6683 [tcl:DEBUG]: TclHandler::set_value : OUT_MSG [ TLIB.MsgInstructions ] = String(SendToAllClients)
@13:09:52.6683 [tcl:DEBUG]: TclHandler::get_value : OUT_MSG [ TLIB.Message.Id ] = String(EventLinkDisconnected)
13:09:52.668 Trc 29044 Sent message :00.00.00.00.00.00.01.34:EventLinkDisconnected.
@13:09:52.6685 [tcl:DEBUG2]: App Sent:    Type = Request
  Id = "00.00.00.00.00.00.01.34"
  Call Id = (null)
  Data = ...
  Offset = 0
  Properties =
        [RouteDest] = String(tserver)
        [TLIB] = Properties:
              [Message] = Properties:
                  [Id] = String(EventLinkDisconnected)
              [MsgInstructions] = String(SendToAllClients)

@13:09:52.6689 [tcl:DEBUG]: Notify End Call: (null)
@13:09:52.6691 [0] 7.5.016.00 send_to_all: message EventLinkDisconnected
AttributeEventSequenceNumber 0000000000000017
AttributeServerStartTime 498c1a2d000c58d8 (13:08:29.809176)
AttributeTimeinuSecs 669099
AttributeTimeinSecs 1233918592 (13:09:52)
13:09:52.669 Trc 04542 EventLinkDisconnected sent to [15] (00000002 I-Server_750_buc IP[XXX.XX.XX.XX]:50496)
13:09:52.669 Std 20002 CTI Link disconnected
LCA_set_AppLiveStatus(APP_STATUS_SERVICE_UNAVAILABLE)
@13:09:52.6693 [ISCC] Trace: Broadcast to all connected servers: message ISCCEventLinkDisconnected
@13:09:52.6693 [ISCC] Debug: Resource 4338: inaccessible
@13:09:52.6693 [ISCC] Debug: Resource 4338: inactive
@13:09:52.6694 [ISCC] Debug: Resource 4339: inaccessible
@13:09:52.6694 [ISCC] Debug: Resource 4339: inactive
@13:09:52.6694 [ISCC] Debug: Resource 4401: inaccessible
@13:09:52.6694 [ISCC] Debug: Resource 4401: inactive
@13:09:52.6694 [ISCC] Debug: Resource 4402: inaccessible
@13:09:52.6694 [ISCC] Debug: Resource 4402: inactive
@13:09:52.6694 [ISCC] Debug: Resource 4403: inaccessible
@13:09:52.6694 [ISCC] Debug: Resource 4403: inactive
@13:09:52.6694 [ISCC] Debug: Resource 4404: inaccessible
@13:09:52.6694 [ISCC] Debug: Resource 4404: inactive
@13:09:52.6694 [ISCC] Debug: Resource 4405: inaccessible
@13:09:52.6694 [ISCC] Debug: Resource 4405: inactive
13:09:52.669 Trc 04541 Message EventLinkDisconnected received from 65200 ( 'TServer_IVR_750_buc')
@13:09:52.6699 [0] message EventLinkDisconnected
AttributeTimeinSecs 1233918592 (13:09:52)
AttributeTimeinuSecs 669099
AttributeServerStartTime 498c1a2d000c58d8 (13:08:29.809176)
AttributeEventSequenceNumber 0000000000000017
@13:09:52.6701 [tcl:DEBUG2]: App Received:    Type = Indication
  Id = "00.00.00.00.00.00.01.36"
  Call Id = "00.00.00.00.00.00.00.17"
  Data = ...
  Offset = 0
  Properties =
        [TLIB] = Properties:
              [ClientName] = String(TServer_IVR_750_buc)
              [Message] = Properties:
                  [AttributeEventSequenceNumber] = OctetString("00.00.00.00.00.00.00.17")
                  [AttributeServerStartTime] = OctetString("49.8c.1a.2d.00.0c.58.d8")
                  [AttributeTimeinSecs] = Int(1233918592)
                  [AttributeTimeinuSecs] = Int(669099)
                  [Id] = String(EventLinkDisconnected)

13:09:52.670 Trc 29043 Received message 00.00.00.00.00.00.00.17:00.00.00.00.00.00.01.36:Link Disconnected.
@13:09:52.6705 [tcl:DEBUG]: TclHandler::get_value : USER_DATA [ Name ] = String(TServer_IVR_750_buc)
@13:09:52.6706 [tcl:DEBUG]: TclHandler::get_value : USER_DATA [ Name ] = String(TServer_IVR_750_buc)
@13:09:59.9885 [tcl:DEBUG2]: TimerManager::timerExpired: localId: 2 conn id: 106954777
@13:09:59.9887 [tcl:DEBUG2]: TimerManager::timerExpired: generating time out event: Stop Waiting Timeout for call: 00.00.00.00.00.00.00.2f
@13:09:59.9891 [tcl:DEBUG]: TclHandler::get_value : USER_DATA [ IVROpMode ] = Int(1)
@13:09:59.9894 [tcl:DEBUG]: TclHandler::value_exists : USER_DATA [ Licensed ] exists
@13:09:59.9895 [tcl:DEBUG]: TclHandler::get_value : ENV_DATA [ GLM.IVR.ActiveBehindCalls ] = Int(1)
@13:09:59.9895 [tcl:DEBUG]: TclHandler::set_value : ENV_DATA [ GLM.IVR.ActiveBehindCalls ] = Int(0)
@13:09:59.9896 [tcl:DEBUG]: TclHandler::erase_value : USER_DATA [ Licensed ]
@13:09:59.9897 [tcl:DEBUG2]: stop: local id: 0 conn id: 127926275
@13:09:59.9898 [tcl:DEBUG2]: stop: local id: 1 conn id: 117440538
@13:09:59.9899 [tcl:DEBUG]: Notify End Call: 00.00.00.00.00.00.00.2f
[/code]


Thanks

[René]

Hi,

I've checked ivr_driver log and I'm not sure your application works is written in the right way. I see following steps:

1. Application issues NotifyCallStart and receives successful answer "OK"
2. Application issues GetCallInfo with parameter "DNIS" - failed (returned "NULL")
3. Application issues GetCallInfo with parameter "ANI" - failed (returned "NULL")

Steps 2 and 3 are wrong. Your application has to issue GetCallInfo(EventName) after successful "NotifyCallStart". Your application should receive one of these values - "EventEstablished", "EventAttachedDataChanged" or "EventPartyChanged". It's necessary to repeat* this step in case receiving no response. Once you receive correct answer you can issue GetCallInfo for DNIS, ANI etc.

* You should limit number of attempts to avoid cycle in your IVR application code. If you don't get correct answer after 2 or 3 calls your application should consider CTI functions aren't available.

R.

[bogdan]

Hello, again me...

GetCallInfo(EventName) should be issued in this exact way? or EventName has to be replaced with a certain value?

Thanks

[René]

I don't have real experience with Periphonics IVR so don't beat me if I'm wrong . Function GetCallInfo has only one parameter of type "String". So I would say your app should issue following call - GetCallInfo("EventName").

R.

PS. You can find details about supported function in the administrator's guide.

[bogdan]

Thank you very much for your help, I'll modify my application immediately.

[quote]
Call Information Functions
              GetCallInfo
              This function requests information related to an active call.
              Input
              String TypeInfo
                  The type of requested information. Table 2 lists the possible TypeInfo
                  values.
                  Note: If a particular value (for example, ANI) is not available, the string
                          NULL is returned by default.

[code]
EventName - Name of the last event received on the current IVR channel
[/code]

Output
Number Result
    If = 0, the function failed.
    If = Request ID, a Request ID can be used later with the GetReply function.
String Info
    The requested information from the call database.

[/quote]

[bogdan]

Even more mind bothering ... I call from my IVR application GetCI1 which should be translated into GetCallInfo(EventName) as you can see from my attached .ppr file.

[code]block:
(
[b]name: GetCI1
X: 414
Y: 112
notes: "Ensure that the Iserver is ready by requesting
the last event and checking that it is event established. (will occur after a NotfyCallStart, and
the Iserver is ready)"
user:
(
type: GetCallInfo
number: 4
parm: System.SystemNumber
parm: System.ApplicationNumber
parm: "\"EventName\" "
parm: Genesys-CTP.iRetValue
)[/b]
next_block: GetRpl?
)[/code]


but all I can see in the logs of the TServerIVR is the call GetCallInfo Type = "LastEvent" with Call State = "Unknown":

[code]
02/09/09 14:50:18.858 FL|00000000|IVR_mpsbuc14:::IP[XXX.XX.XX.XX]:7100:  DRIVER accept connection from IP[YYY.YY.YY.YYY], port 54314, socket 12
02/09/09 14:50:18.961 AP>00000004|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  NoteCallStart Call ID = " 5000", DNIS = "", ANI = "", CDT Tag = "" with Call State = Unknown, Driver version = 7.5.000.06, ILibrary version = 7.5.004.00, IServer version = 7.5.016.00, DTD version = 4.0, Active calls = 1, Outstanding request id's = 0
02/09/09 14:50:18.961 XM|00000004|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  Sent    on socket <IVR_mpsbuc14:7100:IP[XXX.XX.XX.XX]> XML message <<?xml version="1.0" encoding="iso-8859-1"?><!DOCTYPE GctiMsg SYSTEM "IServer.dtd"><GctiMsg><CallId>IVR_mpsbuc14�20�2</CallId><NewCall CallControlMode="Network" Version="4.0"><CalledNum>20</CalledNum></NewCall></GctiMsg>>
02/09/09 14:50:18.961 IS<00000004|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  NewCall Call ID = " 5000", DNIS = "", ANI = "", CDT Tag = ""
02/09/09 14:50:18.961 AP<00000004|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  NoteCallStart rc=0
02/09/09 14:50:18.970 AP>ffffffff|IVR_mpsbuc14:::::                                    Timeout value changed from 5000 to 50
02/09/09 14:50:18.970 AP>00000004|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply request id = 00000004
02/09/09 14:50:18.970 AP<00000004|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply "OK"
02/09/09 14:50:18.980 AP>00000005|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetCallInfo Type = "LastEvent" with Call State = "Unknown"
02/09/09 14:50:18.980 AP<00000005|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetCallInfo rc=0
02/09/09 14:50:18.990 AP>00000005|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply request id = 00000005
02/09/09 14:50:18.990 AP<00000005|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply "NULL"
02/09/09 14:50:20.010 AP>00000006|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetCallInfo Type = "LastEvent" with Call State = "Unknown"
02/09/09 14:50:20.011 AP<00000006|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetCallInfo rc=0
02/09/09 14:50:20.020 AP>00000006|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply request id = 00000006
02/09/09 14:50:20.020 AP<00000006|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply "NULL"
02/09/09 14:50:21.040 AP>00000007|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetCallInfo Type = "LastEvent" with Call State = "Unknown"
02/09/09 14:50:21.040 AP<00000007|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetCallInfo rc=0
02/09/09 14:50:21.050 AP>00000007|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply request id = 00000007
02/09/09 14:50:21.050 AP<00000007|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply "NULL"
02/09/09 14:50:22.070 AP>00000008|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetCallInfo Type = "LastEvent" with Call State = "Unknown"
02/09/09 14:50:22.070 AP<00000008|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetCallInfo rc=0
02/09/09 14:50:22.080 AP>00000008|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply request id = 00000008
02/09/09 14:50:22.080 AP<00000008|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply "NULL"
02/09/09 14:50:23.100 AP>00000009|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetCallInfo Type = "LastEvent" with Call State = "Unknown"
02/09/09 14:50:23.101 AP<00000009|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetCallInfo rc=0
02/09/09 14:50:23.110 AP>00000009|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply request id = 00000009
02/09/09 14:50:23.110 AP<00000009|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply "NULL"
02/09/09 14:50:24.130 AP>0000000a|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetCallInfo Type = "LastEvent" with Call State = "Unknown"
02/09/09 14:50:24.130 AP<0000000a|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetCallInfo rc=0
02/09/09 14:50:24.140 AP>0000000a|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply request id = 0000000a
02/09/09 14:50:24.140 AP<0000000a|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply "NULL"
02/09/09 14:50:25.160 AP>0000000b|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetCallInfo Type = "LastEvent" with Call State = "Unknown"
02/09/09 14:50:25.160 AP<0000000b|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetCallInfo rc=0
02/09/09 14:50:25.170 AP>0000000b|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply request id = 0000000b
02/09/09 14:50:25.170 AP<0000000b|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply "NULL"
02/09/09 14:50:26.190 AP>0000000c|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetCallInfo Type = "LastEvent" with Call State = "Unknown"
02/09/09 14:50:26.190 AP<0000000c|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetCallInfo rc=0
02/09/09 14:50:26.200 AP>0000000c|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply request id = 0000000c
02/09/09 14:50:26.200 AP<0000000c|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply "NULL"
02/09/09 14:50:27.220 AP>0000000d|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetCallInfo Type = "LastEvent" with Call State = "Unknown"
02/09/09 14:50:27.220 AP<0000000d|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetCallInfo rc=0
02/09/09 14:50:27.230 AP>0000000d|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply request id = 0000000d
02/09/09 14:50:27.230 AP<0000000d|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply "NULL"
02/09/09 14:50:28.250 AP>0000000e|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetCallInfo Type = "LastEvent" with Call State = "Unknown"
02/09/09 14:50:28.250 AP<0000000e|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetCallInfo rc=0
02/09/09 14:50:28.260 AP>0000000e|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply request id = 0000000e
02/09/09 14:50:28.260 AP<0000000e|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply "NULL"
02/09/09 14:50:28.270 AP>0000000f|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetCallInfo Type = "DNIS" with Call State = "Unknown"
02/09/09 14:50:28.270 AP<0000000f|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetCallInfo rc=0
02/09/09 14:50:28.280 AP>0000000f|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply request id = 0000000f
02/09/09 14:50:28.280 AP<0000000f|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply "NULL"
02/09/09 14:50:28.290 AP>00000010|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetCallInfo Type = "ANI" with Call State = "Unknown"
02/09/09 14:50:28.290 AP<00000010|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetCallInfo rc=0
02/09/09 14:50:28.300 AP>00000010|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply request id = 00000010
02/09/09 14:50:28.300 AP<00000010|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply "NULL"
02/09/09 14:50:28.310 AP<00000011|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  UDataAddKD rc=-1, Cannot process this API request with a call not at least in ringing, status state = "Unknown"
02/09/09 14:50:28.320 AP<00000012|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  CallTransfer rc=-1, Cannot process this API request with a call not established, status state = "Unknown"
02/09/09 14:50:28.440 AP>00000013|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  NoteCallEnd with Call State = "Unknown"
02/09/09 14:50:28.440 XM|00000013|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  Sent    on socket <IVR_mpsbuc14:7100:IP[XXX.XX.XX.XX]> XML message <<?xml version="1.0" encoding="iso-8859-1"?><!DOCTYPE GctiMsg SYSTEM "IServer.dtd"><GctiMsg><CallId>IVR_mpsbuc14�20�2</CallId><EndCall EndCause="Normal"><ExtnsEx><Node Name="GCTIActiveRelease" Type="Str" Val="false" /></ExtnsEx></EndCall></GctiMsg>>
02/09/09 14:50:28.440 IS<00000013|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  EndCall
02/09/09 14:50:28.440 AP<00000013|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  NoteCallEnd rc=0
02/09/09 14:50:28.450 AP>00000013|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply request id = 00000013
02/09/09 14:50:28.450 AP<00000013|IVR_mpsbuc14:20:IVR_mpsbuc14�20�2:IP[XXX.XX.XX.XX]:7100:  GetReply "OK"
[/code]

if you grep the testCTI.ppr you will never get a matching LastEvent.

As for the TServerIVR nothing changed:
[code]@14:52:57.3639 [xml:DEBUG]: XmlSap::process(): Xml string received = [ <?xml version="1.0" encoding="iso-8859-1"?><!DOCTYPE GctiMsg SYSTEM "IServer.dtd"><GctiMsg><CallId>IVR_mpsbuc
14�20�2</CallId><NewCall CallControlMode="Network" Version="4.0"><CalledNum>20</CalledNum></NewCall></GctiMsg> ]
@14:52:57.3713 [tcl:DEBUG2]: App Received:    Type = Indication
  Id = "00.00.00.00.00.00.01.05"
  Call Id = "00.00.00.00.00.00.00.25"
  Data = ...
  Offset = 6
  Properties =
[GLI] = Properties:
[AppId] = Int(0)
[Circuit] = Int(1)
[Group] = Int(-1)
[Version] = Int(2)
[XML] = Properties:
[Encoding] = String(iso-8859-1)
[Message] = Properties:
  [GctiMsg] = Properties:
[CallId] = Properties:
                            [Val] = String(IVR_mpsbuc14�20�2)
[NewCall] = Properties:
                            [Attrs] = Properties:
  [CallControlMode] = String(Network)
                                  [Version] = String(4.0)
                            [CalledNum] = Properties:
                                  [Val] = String(20)
              [Version] = String(1.0)

14:52:57.371 Trc 29043 Received message 00.00.00.00.00.00.00.25:00.00.00.00.00.00.01.05:New Call Network.
@14:52:57.3719 [tcl:DEBUG2]: TimerManager::startTimer: local id: 0 , conn id: 153092122 , period: 28800000
@14:52:57.3728 [tcl:DEBUG]: TclHandler::copy_value : IN_MSG [ GLI.Group ] -> USER_DATA [ GLI.Group ]
@14:52:57.3729 [tcl:DEBUG]: TclHandler::copy_value : IN_MSG [ GLI.Circuit ] -> USER_DATA [ GLI.Circuit ]
@14:52:57.3730 [tcl:DEBUG]: TclHandler::get_value : IN_MSG [ XML.Message.GctiMsg.NewCall.CalledNum.Val ] = String(20)
@14:52:57.3732 [tcl:DEBUG]: TclHandler::get_value : IN_MSG [ XML.Message.GctiMsg.NewCall.Attrs.Version ] = String(4.0)
@14:52:57.3733 [tcl:DEBUG]: TclHandler::get_value : IN_MSG [ XML.Message.GctiMsg.NewCall.ANI.Val ]: set to default val:
@14:52:57.3734 [tcl:DEBUG]: TclHandler::get_value : IN_MSG [ XML.Message.GctiMsg.NewCall.DNIS.Val ]: set to default val:
@14:52:57.3740 [tcl:DEBUG]: TclHandler::value_exists : ENV_DATA [ TLIB.DNList.20 ] does not exist
@14:52:57.3740 [tcl:DEBUG]: TclHandler::get_value : IN_MSG [ GLI.Group ] = Int(-1)
@14:52:57.3741 [tcl:DEBUG]: TclHandler::get_value : IN_MSG [ GLI.Circuit ] = Int(1)
@14:52:57.3742 [tcl:DEBUG]: TclHandler::set_value : USER_DATA [ INFO.PortDN ] = String(898719)
@14:52:57.3743 [tcl:DEBUG]: TclHandler::set_value : USER_DATA [ TSClient ] = String(TServer_IVR_750_buc)
@14:52:57.3744 [tcl:DEBUG]: TclHandler::set_value : USER_DATA [ ThisDN ] = String(898719)
@14:52:57.3744 [tcl:DEBUG]: TclHandler::set_value : USER_DATA [ RouteDN ] = String(898719)
@14:52:57.3745 [tcl:DEBUG]: TclHandler::set_value : USER_DATA [ IVROpMode ] = Int(1)
@14:52:57.3747 [tcl:DEBUG]: TclHandler::get_value : USER_DATA [ IVROpMode ] = Int(1)
@14:52:57.3747 [tcl:DEBUG]: TclHandler::get_value : ENV_DATA [ GLM.LicensedForIVRBehind ] = Bool(true)
@14:52:57.3749 [tcl:DEBUG]: TclHandler::value_exists : USER_DATA [ Licensed ] does not exist
@14:52:57.3750 [tcl:DEBUG]: TclHandler::get_value : ENV_DATA [ GLM.IVR.ActiveBehindCalls ] = Int(0)
@14:52:57.3751 [tcl:DEBUG]: TclHandler::set_value : ENV_DATA [ GLM.IVR.ActiveBehindCalls ] = Int(1)
@14:52:57.3751 [tcl:DEBUG]: TclHandler::get_value : ENV_DATA [ GLM.IVR.MaxBehindCallsForInterval ] = Int(0)
@14:52:57.3752 [tcl:DEBUG]: TclHandler::set_value : ENV_DATA [ GLM.IVR.MaxBehindCallsForInterval ] = Int(1)
@14:52:57.3752 [tcl:DEBUG]: TclHandler::set_value : USER_DATA [ Licensed ] = Bool(true)
@14:52:57.3753 [tcl:DEBUG]: TclHandler::get_value : IN_MSG [ XML.Encoding ] = String(iso-8859-1)
@14:52:57.3754 [tcl:DEBUG]: TclHandler::set_value : USER_DATA [ DestEncoder ] = String(ISO-8859-1)
@14:52:57.3754 [tcl:DEBUG]: TclHandler::copy_value : IN_MSG [ XML.Message.GctiMsg.CallId.Val ] -> USER_DATA [ CallID ]
@14:52:57.3755 [tcl:DEBUG]: TclHandler::get_value : GLOBAL_DATA [ FlowControl ] = Bool(false)
@14:52:57.3757 [tcl:DEBUG]: TclHandler::create_msg : Created message: ( 00.00.00.00.00.00.00.25 00.00.00.00.00.00.01.06 )
@14:52:57.3758 [tcl:DEBUG]: TclHandler::set_value : OUT_MSG [ Type ] = String(NewCall)
@14:52:57.3758 [tcl:DEBUG]: TclHandler::copy_value : USER_DATA [ TSClient ] -> OUT_MSG [ ClientName ]
@14:52:57.3759 [tcl:DEBUG]: TclHandler::copy_value : USER_DATA [ ThisDN ] -> OUT_MSG [ DN ]
14:52:57.376 Trc 29044 Sent message 00.00.00.00.00.00.00.25:00.00.00.00.00.00.01.06:NewCall.
@14:52:57.3761 [tcl:DEBUG2]: App Sent:   Type = Notify
  Id = "00.00.00.00.00.00.01.06"
  Call Id = "00.00.00.00.00.00.00.25"
  Data = ...
  Offset = 0
  Properties =
[ClientName] = String(TServer_IVR_750_buc)
[DN] = String(898719)
[Type] = String(NewCall)

@14:52:57.3762 [tcl:DEBUG]: TclHandler::timer : cmd: timer_start timerName: wait-for-ringing
@14:52:57.3762 [tcl:DEBUG2]: TimerManager::startTimer: local id: 1 , conn id: 142606358 , period: 60000
@14:52:57.3763 [tcl:DEBUG]: TclHandler::set_condition : add blocking condition = Established
@14:52:57.3764 [tcl:DEBUG]: TclHandler::set_condition : add blocking condition = Ringing
@14:52:57.3764 [tcl:DEBUG]: TclHandler::set_condition : add non-blocking condition = Party Changed
@14:52:57.3765 [tcl:DEBUG]: TclHandler::get_value : USER_DATA [ ThisDN ] = String(898719)
@14:52:57.3765 [tcl:DEBUG]: TclHandler::set_value : USER_DATA [ CallType ] = Int(2)
@14:52:57.3766 [tcl:DEBUG]: TclHandler::copy_value : IN_MSG [ XML.Message.GctiMsg.NewCall.CalledNum.Val ] -> USER_DATA [ INFO.CalledNum ]
@14:52:57.3767 [tcl:DEBUG]: TclHandler::copy_value : IN_MSG [ XML.Message.GctiMsg.NewCall.ANI.Val ] does not exist
@14:52:57.3767 [tcl:DEBUG]: TclHandler::copy_value : IN_MSG [ XML.Message.GctiMsg.NewCall.DNIS.Val ] does not exist
@14:52:57.3770 [tcl:DEBUG]: TclHandler::sub_call : created sub call for call id: 00.00.00.00.00.00.00.25
@14:52:57.3771 [tcl:DEBUG]: TclHandler::sub_call : created sub call for call id: 00.00.00.00.00.00.00.25
@14:52:57.3772 [tcl:DEBUG]: TclHandler::sub_call : created sub call for call id: 00.00.00.00.00.00.00.25
@14:52:57.3773 [tcl:DEBUG]: TclHandler::erase_value : USER_DATA [ MultipleParty ]
@14:52:57.3774 [tcl:DEBUG]: TclHandler::sub_call : created sub call for call id: 00.00.00.00.00.00.00.25
@14:52:57.3775 [tcl:DEBUG]: TclHandler::sub_call : created sub call for call id: 00.00.00.00.00.00.00.25
@14:52:57.3777 [tcl:DEBUG]: TclHandler::value_exists : USER_DATA [ RoutingStarted ] does not exist
@14:52:57.3777 [tcl:DEBUG]: TclHandler::get_value : USER_DATA [ IVROpMode ] = Int(1)
@14:52:57.3778 [tcl:DEBUG]: TclHandler::set_condition : add non-blocking condition = Call Info
@14:52:57.3778 [tcl:DEBUG]: TclHandler::set_condition : add non-blocking condition = Log Message
@14:52:57.3779 [tcl:DEBUG]: TclHandler::set_value : USER_DATA [ Version ] = String(4.0)
14:52:57.552 Trc 04541 Message EventOffHook received from 65201 ( 'buc_tserver_p')
@14:52:57.5529 [0] message EventOffHook
AttributeThisDN '898719'
AttributeTimeinSecs 1234183977 (14:52:57)
AttributeTimeinuSecs 550721
AttributeEventSequenceNumber 000000000bce52ae
14:52:57.553 Trc 04541 Message EventEstablished received from 65201 ( 'buc_tserver_p')
@14:52:57.5533 [0] message EventEstablished
AttributeCallType 2
AttributeCallID 18102150
AttributeConnID 006c01a54474bd1f
AttributeCallUUID '000A2ADA-2728-1990-A640-AC103133AA77'
AttributeUserData [64] 00 03 00 00..
'k_ani' '0[MYPHONENUMBER]'
'k_home_location' 'buc'
'k_from_ivr' 'true'
AttributeANI '[MYPHONENUMBER]'
AttributeThisDN '898719'
AttributeThisDNRole 2
AttributeThisTrunk 2055
AttributeOtherTrunk 10448
AttributeOtherDNRole 1
AttributeOtherDN '[MYPHONENUMBER]'
AttributeCallState 0
AttributeTimeinSecs 1234183977 (14:52:57)
AttributeTimeinuSecs 551197
AttributeEventSequenceNumber 000000000bce52af
@14:52:57.5535 [tcl:DEBUG2]: App Received:    Type = Indication
  Id = "00.00.00.00.00.00.01.07"
  Call Id = "00.00.00.00.00.00.00.18"
  Data = ...
  Offset = 0
  Properties =
[TLIB] = Properties:
              [ClientName] = String(buc_tserver_p)
              [Message] = Properties:
                  [AttributeEventSequenceNumber] = OctetString("00.00.00.00.0b.ce.52.ae")
                  [AttributeThisDN] = String(898719)
                  [AttributeTimeinSecs] = Int(1234183977)
                  [AttributeTimeinuSecs] = Int(550721)
                  [Id] = String(EventOffHook)

14:52:57.553 Trc 29043 Received message 00.00.00.00.00.00.00.18:00.00.00.00.00.00.01.07:Off Hook.
@14:52:57.5542 [tcl:DEBUG]: TclHandler::set_condition : add non-blocking condition = Ignorable
@14:53:06.8428 [gli:WARN]: request for fd: 17
@14:53:06.8429 [gli:DEBUG]: Receiving message on ( -1 , 1 )
fd = 17
localAddr = IP[XXX.XX.XX.XX]:7100
remoteAddr = IP[YYY.YY.YY.YYY]:54308
@14:53:06.8430 [gli:DEBUG3]: Read:
    0: 00 03 00 f9 02 00 3c 3f 78 6d 6c 20 76 65 72 73 * ......<?xml vers
  16: 69 6f 6e 3d 22 31 2e 30 22 20 65 6e 63 6f 64 69 * ion="1.0" encodi
  32: 6e 67 3d 22 69 73 6f 2d 38 38 35 39 2d 31 22 3f * ng="iso-8859-1"?
  48: 3e 3c 21 44 4f 43 54 59 50 45 20 47 63 74 69 4d * ><!DOCTYPE GctiM
  64: 73 67 20 53 59 53 54 45 4d 20 22 49 53 65 72 76 * sg SYSTEM "IServ
  80: 65 72 2e 64 74 64 22 3e 3c 47 63 74 69 4d 73 67 * er.dtd"><GctiMsg
  96: 3e 3c 43 61 6c 6c 49 64 3e 49 56 52 5f 6d 70 73 * ><CallId>IVR_mps
  112: 62 75 63 31 34 ff 32 30 ff 32 3c 2f 43 61 6c 6c * buc14.20.2</Call
  128: 49 64 3e 3c 45 6e 64 43 61 6c 6c 20 45 6e 64 43 * Id><EndCall EndC
  144: 61 75 73 65 3d 22 4e 6f 72 6d 61 6c 22 3e 3c 45 * ause="Normal"><E
  160: 78 74 6e 73 45 78 3e 3c 4e 6f 64 65 20 4e 61 6d * xtnsEx><Node Nam
  176: 65 3d 22 47 43 54 49 41 63 74 69 76 65 52 65 6c * e="GCTIActiveRel
  192: 65 61 73 65 22 20 54 79 70 65 3d 22 53 74 72 22 * ease" Type="Str"
  208: 20 56 61 6c 3d 22 66 61 6c 73 65 22 20 2f 3e 3c *  Val="false" /><
  224: 2f 45 78 74 6e 73 45 78 3e 3c 2f 45 6e 64 43 61 * /ExtnsEx></EndCa
  240: 6c 6c 3e 3c 2f 47 63 74 69 4d 73 67 3e * ll></GctiMsg>
@14:53:06.8433 [xml:DEBUG]: XmlSap::process(): Xml string received = [ <?xml version="1.0" encoding="iso-8859-1"?><!DOCTYPE GctiMsg SYSTEM "IServer.dtd"><GctiMsg><CallId>IVR_mpsbuc
14�20�2</CallId><EndCall EndCause="Normal"><ExtnsEx><Node Name="GCTIActiveRelease" Type="Str" Val="false" /></ExtnsEx></EndCall></GctiMsg> ]
@14:53:06.8517 [tcl:DEBUG2]: App Received:    Type = Indication
[/code]


Regards

[René]

Could you put a pause of 500ms or 1 second before repeating GetCallInfo("EventName")?

Time in ivr_driver log and IVR TServer log is different. Is that because time on IVR/IVRTServer hosts isn't synchronized? Could you synchronize it?

R.

[bogdan]

I'll try to put a sleep delay... but I can't syncronize the machine right away (i know of this "issue" for quite a while) because this machines are administered by two different departments.

But I do not think that is a problem because CTI matches calls by ConnectionID.

thanks

[René]

Time difference isn't problem. It just make analysis of the logs hard as it impossible to match requests/responses by time.

R.

[bogdan]

I'm getting very tired of the genesys support...
Thank you very much Rene for your interest.

[bogdan]

Finally the solution came to my mind as I found out that [quote]In behind mode the IVR Server should be receiving messages concerning the DN from the premise TServer, but instead it is receiving messages from the TServer_IVR.[/quote]

The problem was that the TServerIVR must have it's own switch on which only the IVRports must be declared and the association DNs must be on the PremiseTserver switch.

IVR Driver call trace log:

[code]

02/11/09 11:48:26.477 FL|00000000|IVR_mpsbuc14:::IP[XXX.XX.XX.XX]:7100:                                      DRIVER accept connection from IP[YYY.YY..YY.YYY], port 56364, socket 12
02/11/09 11:48:26.580 AP>000000db|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:                  NoteCallStart Call ID = " 5000", DNIS = "", ANI = "", CDT Tag = "" with Call State = "Released", Driver version = 7.5.000.06, ILibrary version = 7.5.004.00, IServer version = 7.5.016.00, DTD version = 4.0, Active calls = 1, Outstanding request id's = 7 02/11/09 11:48:26.581 XM|000000db|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:                  Sent    on socket <IVR_mpsbuc14:7100:IP[XXX.XX.XX.XX]> XML message <<?xml version="1.0" encoding="iso-8859-1"?><!DOCTYPE GctiMsg SYSTEM "IServer.dtd"><GctiMsg><CallId>IVR_mpsbuc14\ufffd20\ufffd28</CallId><NewCall CallControlMode="Network" Version="4.0"><CalledNum>20</CalledNum></NewCall></GctiMsg>>
02/11/09 11:48:26.581 IS<000000db|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:                  NewCall Call ID = " 5000", DNIS = "", ANI = "", CDT Tag = ""
02/11/09 11:48:26.581 AP<000000db|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:                  NoteCallStart rc=0
02/11/09 11:48:26.590 AP>000000db|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:                  GetReply request id = 000000db
02/11/09 11:48:26.590 AP<000000db|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:                  GetReply "OK"
02/11/09 11:48:26.600 AP>000000dc|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:                  GetCallInfo Type = "LastEvent" with Call State = "Unknown"
02/11/09 11:48:26.600 AP<000000dc|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:                  GetCallInfo rc=0
02/11/09 11:48:26.601 XM|ffffffff|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:                  Received on socket <IVR_mpsbuc14:7100:IP[XXX.XX.XX.XX]> XML message <<?xml version='1.0' encoding='ISO-8859-1'?><!DOCTYPE GctiMsg SYSTEM 'IServer.dtd'><GctiMsg><CallId>IVR_mpsbuc14\ufffd20\ufffd28</CallId><CallStatus Event='Ringing'/></GctiMsg>>
02/11/09 11:48:26.601 IS>ffffffff|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:                  CallStatus "Ringing"
02/11/09 11:48:26.601 XM|ffffffff|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:                  Received on socket <IVR_mpsbuc14:7100:IP[XXX.XX.XX.XX]> XML message <<?xml version='1.0' encoding='ISO-8859-1'?><!DOCTYPE GctiMsg SYSTEM 'IServer.dtd'><GctiMsg><CallId>IVR_mpsbuc14\ufffd20\ufffd28</CallId><CallStatus Event='Established'/></GctiMsg>>
02/11/09 11:48:26.601 IS>ffffffff|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:                  CallStatus "Established"
02/11/09 11:48:26.610 AP>000000dc|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:                  GetReply request id = 000000dc
02/11/09 11:48:26.610 AP<000000dc|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:                  GetReply "NULL"
02/11/09 11:48:27.630 AP>000000dd|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:                  GetCallInfo Type = "LastEvent" with Call State = "Established"
02/11/09 11:48:27.630 XM|000000dd|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:                  Sent    on socket <IVR_mpsbuc14:7100:IP[XXX.XX.XX.XX]> XML message <<?xml version="1.0" encoding="iso-8859-1"?><!DOCTYPE GctiMsg SYSTEM "IServer.dtd"><GctiMsg><CallId>IVR_mpsbuc14\ufffd20\ufffd28</CallId><CallInfoReq></CallInfoReq></GctiMsg>>
02/11/09 11:48:27.630 IS<000000dd|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:                  CallInfoReq
02/11/09 11:48:27.630 AP<000000dd|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:                  GetCallInfo rc=0
02/11/09 11:48:27.650 XM|ffffffff|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:                  Received on socket <IVR_mpsbuc14:7100:IP[XXX.XX.XX.XX]> XML message <<?xml version='1.0' encoding='ISO-8859-1'?><!DOCTYPE GctiMsg SYSTEM 'IServer.dtd'><GctiMsg><CallId>IVR_mpsbuc14\ufffd20\ufffd28</CallId><CallInfoResp ANI='[MYPHONENUMBER]' CalledNum='20' ConnId='006c01a54478f992' TSCallId='18101075' PortDN='898719' PortTrunk='2055' OtherDN='[MYPHONENUMBER]' OtherTrunk='10268' LastEvent='EventEstablished'/></GctiMsg>>
02/11/09 11:48:27.650 IS>000000dd|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  CallInfoResp ANI = "[MYPHONENUMBER]" CalledNum = "20" ConnID = "006c01a54478f992" LastEvent = "EventEstablished" OtherDN = "[MYPHONENUMBER]" OtherTrunk = "10268" PortDN = "898719" PortTrunk = "2055" TSCallId = "18101075" 02/11/09 11:48:27.660 AP>000000dd|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  GetReply request id = 000000dd
02/11/09 11:48:27.660 AP<000000dd|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  GetReply "EventEstablished"
02/11/09 11:48:27.670 AP>000000de|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  GetCallInfo Type = "DNIS" with Call State = "Established"
02/11/09 11:48:27.670 XM|000000de|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  Sent    on socket <IVR_mpsbuc14:7100:IP[XXX.XX.XX.XX]> XML message <<?xml version="1.0" encoding="iso-8859-1"?><!DOCTYPE GctiMsg SYSTEM "IServer.dtd"><GctiMsg><CallId>IVR_mpsbuc14\ufffd20\ufffd28</CallId><CallInfoReq></CallInfoReq></GctiMsg>>
02/11/09 11:48:27.670 IS<000000de|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  CallInfoReq
02/11/09 11:48:27.670 AP<000000de|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  GetCallInfo rc=0
02/11/09 11:48:27.680 XM|ffffffff|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  Received on socket <IVR_mpsbuc14:7100:IP[XXX.XX.XX.XX]> XML message <<?xml version='1.0' encoding='ISO-8859-1'?><!DOCTYPE GctiMsg SYSTEM 'IServer.dtd'><GctiMsg><CallId>IVR_mpsbuc14\ufffd20\ufffd28</CallId><CallInfoResp ANI='[MYPHONENUMBER]' CalledNum='20' ConnId='006c01a54478f992' TSCallId='18101075' PortDN='898719' PortTrunk='2055' OtherDN='[MYPHONENUMBER]' OtherTrunk='10268' LastEvent='EventEstablished'/></GctiMsg>>
02/11/09 11:48:27.680 IS>000000de|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  CallInfoResp ANI = "[MYPHONENUMBER]" CalledNum = "20" ConnID = "006c01a54478f992" LastEvent = "EventEstablished" OtherDN = "[MYPHONENUMBER]" OtherTrunk = "10268" PortDN = "898719" PortTrunk = "2055" TSCallId = "18101075"
02/11/09 11:48:27.680 AP>000000de|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  GetReply request id = 000000de
02/11/09 11:48:27.681 AP<000000de|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  GetReply "NULL"
02/11/09 11:48:27.690 AP>000000df|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  GetCallInfo Type = "ANI" with Call State = "Established"
02/11/09 11:48:27.690 XM|000000df|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  Sent    on socket <IVR_mpsbuc14:7100:IP[XXX.XX.XX.XX]> XML message <<?xml version="1.0" encoding="iso-8859-1"?><!DOCTYPE GctiMsg SYSTEM "IServer.dtd"><GctiMsg><CallId>IVR_mpsbuc14\ufffd20\ufffd28</CallId><CallInfoReq></CallInfoReq></GctiMsg>>
02/11/09 11:48:27.690 IS<000000df|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  CallInfoReq
02/11/09 11:48:27.690 AP<000000df|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  GetCallInfo rc=0
02/11/09 11:48:27.700 XM|ffffffff|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  Received on socket <IVR_mpsbuc14:7100:IP[XXX.XX.XX.XX]> XML message <<?xml version='1.0' encoding='ISO-8859-1'?><!DOCTYPE GctiMsg SYSTEM 'IServer.dtd'><GctiMsg><CallId>IVR_mpsbuc14\ufffd20\ufffd28</CallId><CallInfoResp ANI='[MYPHONENUMBER]' CalledNum='20' ConnId='006c01a54478f992' TSCallId='18101075' PortDN='898719' PortTrunk='2055' OtherDN='[MYPHONENUMBER]' OtherTrunk='10268' LastEvent='EventEstablished'/></GctiMsg>>
02/11/09 11:48:27.700 IS>000000df|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  CallInfoResp ANI = "[MYPHONENUMBER]" CalledNum = "20" ConnID = "006c01a54478f992" LastEvent = "EventEstablished" OtherDN = "[MYPHONENUMBER]" OtherTrunk = "10268" PortDN = "898719" PortTrunk = "2055" TSCallId = "18101075" 02/11/09 11:48:27.700 AP>000000df|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  GetReply request id = 000000df
02/11/09 11:48:27.700 AP<000000df|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  GetReply "[MYPHONENUMBER]"
02/11/09 11:48:27.710 AP>000000e0|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  UDataAddKD key-value pairs = "^^CLI^^[MYPHONENUMBER]^^" with Call State = "Established"
02/11/09 11:48:27.710 XM|000000e0|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  Sent    on socket <IVR_mpsbuc14:7100:IP[XXX.XX.XX.XX]> XML message <<?xml version="1.0" encoding="iso-8859-1"?><!DOCTYPE GctiMsg SYSTEM "IServer.dtd"><GctiMsg><CallId>IVR_mpsbuc14\ufffd20\ufffd28</CallId><UDataSet Action="Replace"><RequestId>224</RequestId><UDataEx><Node Name="CLI" Type="Str" Val="[MYPHONENUMBER]" /></UDataEx></UDataSet></GctiMsg>>
02/11/09 11:48:27.710 IS<000000e0|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  UDataSet key-value pairs = "^^CLI^^[MYPHONENUMBER]^^"
02/11/09 11:48:27.711 AP<000000e0|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  UDataAddKD rc=0
02/11/09 11:48:27.727 XM|ffffffff|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  Received on socket <IVR_mpsbuc14:7100:IP[XXX.XX.XX.XX]> XML message <<?xml version='1.0' encoding='ISO-8859-1'?><!DOCTYPE GctiMsg SYSTEM 'IServer.dtd'><GctiMsg><CallId>IVR_mpsbuc14\ufffd20\ufffd28</CallId><UDataResp Result='Success'><RequestId>224</RequestId></UDataResp></GctiMsg>>
02/11/09 11:48:27.727 IS>ffffffff|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  UDataResp "OK"
02/11/09 11:48:27.740 AP>000000e0|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  GetReply request id = 000000e0
02/11/09 11:48:27.740 AP<000000e0|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  GetReply "OK"
02/11/09 11:48:27.750 AP>000000e1|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  CallTransfer Dest DN = "4091" with Call State = "Established"
02/11/09 11:48:27.750 XM|000000e1|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  Sent    on socket <IVR_mpsbuc14:7100:IP[XXX.XX.XX.XX]> XML message <<?xml version="1.0" encoding="iso-8859-1"?><!DOCTYPE GctiMsg SYSTEM "IServer.dtd"><GctiMsg><CallId>IVR_mpsbuc14\ufffd20\ufffd28</CallId><OneStepXfer DestDN="4091"></OneStepXfer></GctiMsg>>
02/11/09 11:48:27.750 IS<000000e1|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  OneStepXfer
02/11/09 11:48:27.750 AP<000000e1|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  CallTransfer rc=0
02/11/09 11:48:27.810 AP>000000e1|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  GetReply request id = 000000e1
02/11/09 11:48:27.810 AP<000000e1|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  GetReply Timeout, request ID=000000e1, no response has been received from IVR Server.
02/11/09 11:48:27.848 XM|ffffffff|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  Received on socket <IVR_mpsbuc14:7100:IP[XXX.XX.XX.XX]> XML message <<?xml version='1.0' encoding='ISO-8859-1'?><!DOCTYPE GctiMsg SYSTEM 'IServer.dtd'><GctiMsg><CallId>IVR_mpsbuc14\ufffd20\ufffd28</CallId><CallStatus Event='Held'/></GctiMsg>>
02/11/09 11:48:27.849 IS>ffffffff|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  CallStatus "Held"
02/11/09 11:48:27.860 XM|ffffffff|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  Received on socket <IVR_mpsbuc14:7100:IP[XXX.XX.XX.XX]> XML message <<?xml version='1.0' encoding='ISO-8859-1'?><!DOCTYPE GctiMsg SYSTEM 'IServer.dtd'><GctiMsg><CallId>IVR_mpsbuc14\ufffd20\ufffd28</CallId><CallStatus Event='Dialing'/></GctiMsg>>
02/11/09 11:48:27.860 IS>ffffffff|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  CallStatus "Dialing"
02/11/09 11:48:27.870 AP>ffffffff|IVR_mpsbuc14:::::                                                      Timeout value changed from 50 to 0
02/11/09 11:48:27.870 AP>000000e1|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  GetReply request id = 000000e1
02/11/09 11:48:27.870 AP<000000e1|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  GetReply Timeout, request ID=000000e1, no response has been received from IVR Server.
02/11/09 11:48:27.889 XM|ffffffff|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  Received on socket <IVR_mpsbuc14:7100:IP[XXX.XX.XX.XX]> XML message <<?xml version='1.0' encoding='ISO-8859-1'?><!DOCTYPE GctiMsg SYSTEM 'IServer.dtd'><GctiMsg><CallId>IVR_mpsbuc14\ufffd20\ufffd28</CallId><CallStatus Event='XferComplete'/></GctiMsg>>
02/11/09 11:48:27.890 IS>ffffffff|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  CallStatus "XferComplete"
02/11/09 11:48:27.980 AP>000000e1|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  GetReply request id = 000000e1
02/11/09 11:48:27.980 AP<000000e1|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  GetReply "XferComplete"
02/11/09 11:48:28.100 AP>000000e2|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  NoteCallEnd with Call State = "XferComplete"
02/11/09 11:48:28.100 XM|000000e2|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  Sent    on socket <IVR_mpsbuc14:7100:IP[XXX.XX.XX.XX]> XML message <<?xml version="1.0" encoding="iso-8859-1"?><!DOCTYPE GctiMsg SYSTEM "IServer.dtd"><GctiMsg><CallId>IVR_mpsbuc14\ufffd20\ufffd28</CallId><EndCall EndCause="Normal"><ExtnsEx><Node Name="GCTIActiveRelease" Type="Str" Val="false" /></ExtnsEx></EndCall></GctiMsg>>
02/11/09 11:48:28.100 IS<000000e2|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  EndCall
02/11/09 11:48:28.100 AP<000000e2|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:006c01a54478f992  NoteCallEnd rc=0
02/11/09 11:48:28.110 AP>ffffffff|IVR_mpsbuc14:::::                                                      Timeout value changed from 0 to 50
02/11/09 11:48:28.110 AP>000000e2|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:                  GetReply request id = 000000e2
02/11/09 11:48:28.110 AP<000000e2|IVR_mpsbuc14:20:IVR_mpsbuc14\ufffd20\ufffd28:IP[XXX.XX.XX.XX]:7100:                  GetReply "OK"
[/code]


As you can see the call is ok now.

I'll post later a tutorial of how to configure this applications.


Thanks

[René]

Hi,

Great to hear it works but I'm not sure I do understand your explanation. I saw in IVR_TServer log messages (EventRinging etc.) coming from premise TServer so what was wrong?

R.

[bogdan]

The only configuration changes I have made were:

1. I've created a new switch for the IVR ports (and put the TServerIVR on it and IVR ports maping)
2. The association DNs (with the IVR ports) need to remain on the premise TServer switch.

And you were very right with the delay... it seems that it requires a 1sec delay before the call is Established (until then the call state is Ringing)

And a weird that even if the call is in Ringing state I can get the ANI/DNIS parameters but I can't transfer the call

Thx.