Need help - EventAbandoned

[alamitab]

Hello guys.
We have  some abandoned calls in our call canter. The reason seems to be "CiscoCause=CAUSE_USERBUSY", but our agents are in ready state... ?!??!

TServer log:

[sup]@16:12:55.6310 [0] 8.0.001.01 distribute_event: message EventRouteRequest
AttributeEventSequenceNumber 0000000000008986
AttributeTimeinuSecs 631000
AttributeTimeinSecs 1299852775 (16:12:55)
AttributeOtherDNRole 1
AttributeOtherDN '769072241'
AttributeThisDNRole 2
AttributeThisDN '399'
AttributeANI '769072241'
AttributeDNIS '399'
AttributeCallUUID 'PE92V9KD5D7D98MLHVAN5710HS0001TJ'
AttributeConnID 027201e68cb2329e
AttributeCallID 33620666
AttributeCallType 2
AttributeThisQueue '399'
AttributeCallState 0
16:12:55.631 Int 04544 Interaction message "EventRouteRequest" generated
16:12:55.631 Trc 04542 EventRouteRequest sent to [668] (0000014d StatServerCCA_71 151.10.224.47:59954)
16:12:55.631 Trc 04542 EventRouteRequest sent to [620] (0000014c StatServerCCA_71 151.10.224.47:59952)
16:12:55.631 Trc 04542 EventRouteRequest sent to [584] (0000000b StatServer_Tz_EU-E 151.10.224.47:63138)
16:12:55.631 Trc 04542 EventRouteRequest sent to [536] (00000007 StatServer_Tz_EU-E 151.10.224.47:63130)
16:12:55.631 Trc 04542 EventRouteRequest sent to [548] (00000008 StatServerREP 151.10.224.47:63132)
16:12:55.631 Trc 04542 EventRouteRequest sent to [524] (00000006 StatServerREP 151.10.224.47:63125)
16:12:55.631 Trc 04542 EventRouteRequest sent to [512] (00000005 StatServerCCA_80 151.10.203.32:52959)
16:12:55.631 Trc 04542 EventRouteRequest sent to [488] (00000003 StatServerCCA_80 151.10.203.32:52955)
16:12:55.631 Trc 04542 EventRouteRequest sent to [500] (00000004 StatServerREP_80 151.10.203.32:52958)
16:12:55.631 Trc 04542 EventRouteRequest sent to [448] (00000002 StatServerREP_80 151.10.203.32:52954)
16:12:55.631 Trc 04542 EventRouteRequest sent to [608] (0000000d RO_StatServer_72 151.10.230.90:1191)
16:12:55.631 Trc 04542 EventRouteRequest sent to [596] (0000000c RO_StatServer_72 151.10.230.90:1190)
16:12:55.631 Trc 04542 EventRouteRequest sent to [560] (00000009 URServer_Tz_EU-E 151.10.224.47:63134)
@16:12:55.6310 [gctm] Call [027201e68cb2329e/20102ba,sST,tST,l1] Changing state to 1
@16:12:55.6310 [gctm] Call [027201e68cb2329e/20102ba,sOG,tST,l1] Setting timer to OG:1800000mS
@16:12:55.6310 [((1] 1 208 S 9 'CallEv(1)=> Type=ConnCreatedEvent Cause=CAUSE_NORMAL CiscoCause=CAUSE_NOERROR Cid=33620666 CCurCldA=399 CCurClgA=769072241 MetaCode(false)=META_CALL_STARTING Addr=769072241 ConnReason=REASON_DIRECTCALL'
@16:12:55.6310 [((1] 1 14 I 32 33620666
@16:12:55.6310 [tout] Collected jtapi[1] tevent(20:CREATE_CALL)( (20102ba:0)  (:0).
@16:12:55.6310 [((1] 1 180 S 9 'CallEv(1)=> Type=ConnConnectedEvent Cause=CAUSE_NORMAL CiscoCause=CAUSE_NOERROR Cid=33620666 CCurCldA=399 CCurClgA=769072241 MetaCode(true)=META_CALL_PROGRESS Addr=769072241'
@16:12:55.6310 [((1] 1 213 S 9 'CallEv(1)=> Type=CallCtlConnEstablishedEv Cause=CAUSE_NORMAL ECldA=399 EClgA=769072241 CiscoCause=CAUSE_NOERROR Cid=33620666 CCurCldA=399 CCurClgA=769072241 MetaCode(false)=META_CALL_PROGRESS Addr=769072241'
@16:12:55.6310 [tout] >>>Incoming SMEvent, s:468, l:3670, n:'1 RO_VoIP_SM_760', e: CREATE_LEG_ACK(sm_id=1,leg=3670,rtp:8368,rtcp:8369,err=0) ref=795
@16:12:55.6310 [tout] SmLegList::CreateLegResponse: sm = 1, leg = 3670, err = 0, rtp = 8368, rtcp = 8369
@16:12:55.6310 [sm] SmLegOwner::CreateResponse - 0.
16:12:56.772 Trc 04541 RequestUpdateUserData received from [560] (00000009 URServer_Tz_EU-E 151.10.224.47:63134)
message RequestUpdateUserData
AttributeThisDN '399'
AttributeConnID 027201e68cb2329e
AttributeUserData [22] 00 01 00 00..
'Service' 'Customer'
AttributeReferenceID 738
16:12:56.772 Int 04543 Interaction message "RequestUpdateUserData" received from 560 ("URServer_Tz_EU-E")
@16:12:56.7720 Call [027201e68cb2329e]: urid 00020272
@16:12:56.7720 [0] 8.0.001.01 distribute_response: message EventAttachedDataChanged
AttributeEventSequenceNumber 0000000000008987
AttributeTimeinuSecs 772000
AttributeTimeinSecs 1299852776 (16:12:56)
AttributeReferenceID 738
AttributeThirdPartyDN '399'
AttributeThisDNRole 2
AttributeThisDN '399'
AttributeANI '769072241'
AttributeDNIS '399'
AttributeUserData [22] 00 01 00 00..
'Service' 'Customer'
AttributeCallUUID 'PE92V9KD5D7D98MLHVAN5710HS0001TJ'
AttributeConnID 027201e68cb2329e
AttributeCallID 33620666
AttributeCallType 2
16:12:56.772 Int 04544 Interaction message "EventAttachedDataChanged" generated
16:12:56.772 Trc 04542 EventAttachedDataChanged sent to [560] (00000009 URServer_Tz_EU-E 151.10.224.47:63134)
16:12:56.772 Trc 04542 EventAttachedDataChanged sent to [668] (0000014d StatServerCCA_71 151.10.224.47:59954)
16:12:56.772 Trc 04542 EventAttachedDataChanged sent to [620] (0000014c StatServerCCA_71 151.10.224.47:59952)
16:12:56.772 Trc 04542 EventAttachedDataChanged sent to [584] (0000000b StatServer_Tz_EU-E 151.10.224.47:63138)
16:12:56.772 Trc 04542 EventAttachedDataChanged sent to [536] (00000007 StatServer_Tz_EU-E 151.10.224.47:63130)
16:12:56.772 Trc 04542 EventAttachedDataChanged sent to [548] (00000008 StatServerREP 151.10.224.47:63132)
16:12:56.772 Trc 04542 EventAttachedDataChanged sent to [524] (00000006 StatServerREP 151.10.224.47:63125)
16:12:56.772 Trc 04542 EventAttachedDataChanged sent to [512] (00000005 StatServerCCA_80 151.10.203.32:52959)
16:12:56.772 Trc 04542 EventAttachedDataChanged sent to [488] (00000003 StatServerCCA_80 151.10.203.32:52955)
16:12:56.772 Trc 04542 EventAttachedDataChanged sent to [500] (00000004 StatServerREP_80 151.10.203.32:52958)
16:12:56.772 Trc 04542 EventAttachedDataChanged sent to [448] (00000002 StatServerREP_80 151.10.203.32:52954)
16:12:56.772 Trc 04542 EventAttachedDataChanged sent to [608] (0000000d RO_StatServer_72 151.10.230.90:1191)
16:12:56.772 Trc 04542 EventAttachedDataChanged sent to [596] (0000000c RO_StatServer_72 151.10.230.90:1190)
@16:12:56.7720 [gctmi] Distributing request RequestUpdateUserData
@16:12:56.7720 [tout] Call [027201e68cb2329e/20102ba,sOG,tOG,l1] (reqChangeUserData)
@16:12:56.7720 [gctmi] request RequestUpdateUserData removed from reqMgr
16:12:59.116 Trc 04541 RequestUpdateUserData received from [560] (00000009 URServer_Tz_EU-E 151.10.224.47:63134)
message RequestUpdateUserData
AttributeThisDN '399'
AttributeConnID 027201e68cb2329e
AttributeUserData [58] 00 03 00 00..
'ACCOUNT' '0007300219'
'Company' 'SC TENET SRL'
'Accno' ''
AttributeReferenceID 739
16:12:59.116 Int 04543 Interaction message "RequestUpdateUserData" received from 560 ("URServer_Tz_EU-E")
@16:12:59.1160 Call [027201e68cb2329e]: urid 00030272
@16:12:59.1160 [0] 8.0.001.01 distribute_response: message EventAttachedDataChanged
AttributeEventSequenceNumber 0000000000008988
AttributeTimeinuSecs 116000
AttributeTimeinSecs 1299852779 (16:12:59)
AttributeReferenceID 739
AttributeThirdPartyDN '399'
AttributeThisDNRole 2
AttributeThisDN '399'
AttributeANI '769072241'
AttributeDNIS '399'
AttributeUserData [78] 00 04 00 00..
'Service' 'Customer'
'ACCOUNT' '0007300219'
'Company' 'SC TENET SRL'
'Accno' ''
AttributeCallUUID 'PE92V9KD5D7D98MLHVAN5710HS0001TJ'
AttributeConnID 027201e68cb2329e
AttributeCallID 33620666
AttributeCallType 2
16:12:59.116 Int 04544 Interaction message "EventAttachedDataChanged" generated
16:12:59.116 Trc 04542 EventAttachedDataChanged sent to [560] (00000009 URServer_Tz_EU-E 151.10.224.47:63134)
16:12:59.116 Trc 04542 EventAttachedDataChanged sent to [668] (0000014d StatServerCCA_71 151.10.224.47:59954)
16:12:59.116 Trc 04542 EventAttachedDataChanged sent to [620] (0000014c StatServerCCA_71 151.10.224.47:59952)
16:12:59.116 Trc 04542 EventAttachedDataChanged sent to [584] (0000000b StatServer_Tz_EU-E 151.10.224.47:63138)
16:12:59.116 Trc 04542 EventAttachedDataChanged sent to [536] (00000007 StatServer_Tz_EU-E 151.10.224.47:63130)
16:12:59.116 Trc 04542 EventAttachedDataChanged sent to [548] (00000008 StatServerREP 151.10.224.47:63132)
16:12:59.116 Trc 04542 EventAttachedDataChanged sent to [524] (00000006 StatServerREP 151.10.224.47:63125)
16:12:59.116 Trc 04542 EventAttachedDataChanged sent to [512] (00000005 StatServerCCA_80 151.10.203.32:52959)
16:12:59.116 Trc 04542 EventAttachedDataChanged sent to [488] (00000003 StatServerCCA_80 151.10.203.32:52955)
16:12:59.116 Trc 04542 EventAttachedDataChanged sent to [500] (00000004 StatServerREP_80 151.10.203.32:52958)
16:12:59.116 Trc 04542 EventAttachedDataChanged sent to [448] (00000002 StatServerREP_80 151.10.203.32:52954)
16:12:59.116 Trc 04542 EventAttachedDataChanged sent to [608] (0000000d RO_StatServer_72 151.10.230.90:1191)
16:12:59.116 Trc 04542 EventAttachedDataChanged sent to [596] (0000000c RO_StatServer_72 151.10.230.90:1190)
@16:12:59.1160 [gctmi] Distributing request RequestUpdateUserData
@16:12:59.1160 [tout] Call [027201e68cb2329e/20102ba,sOG,tOG,l1] (reqChangeUserData)
@16:12:59.1160 [gctmi] request RequestUpdateUserData removed from reqMgr
@16:12:59.6470 [((1] 1 187 S 9 'CallEv(1)=> Type=ConnDisconnectedEvent Cause=Other: 17 CiscoCause=CAUSE_USERBUSY Cid=33620666 CCurCldA=399 CCurClgA=769072241 MetaCode(true)=META_CALL_REMOVING_PARTY Addr=769072241'
@16:12:59.6470 [((1] 1 219 S 9 'CallEv(1)=> Type=CallCtlConnDisconnectedEv Cause=CAUSE_BUSY ECldA=399 EClgA=769072241 CiscoCause=CAUSE_USERBUSY Cid=33620666 CCurCldA=399 CCurClgA=769072241 MetaCode(false)=META_CALL_REMOVING_PARTY Addr=769072241'
@16:12:59.6470 [((1] 1 55 ISISISIIBI 5 33620666 '769072241' 131 '' 17 '' 2 0 0 0
@16:12:59.6470 [tout] Collected jtapi[1] tevent(5:RELEASED)(769072241:) (20102ba:83)  (:11).
@16:12:59.6470 [gctmi] TMsg [EventReleased(769072241)] distributing to model
@16:12:59.6470 [gctmi] Call [027201e68cb2329e/20102ba,sOG,tOG,l1] distributing EventReleased
@16:12:59.6470 [gctmi] Call [027201e68cb2329e/20102ba,sOG,tOG,l1] processReleased
@16:12:59.6470 [gctmi] Call [027201e68cb2329e/20102ba,sOG,tOG,l1] EvReleased/Abn ignored for non-exist party.
@16:12:59.6470 [((1] 1 173 S 9 'CallEv(1)=> Type=ConnDisconnectedEvent Cause=Other: 17 CiscoCause=CAUSE_USERBUSY Cid=33620666 CCurCldA=399 CCurClgA=769072241 MetaCode(true)=META_CALL_ENDING Addr=399'
@16:12:59.6470 [((1] 1 205 S 9 'CallEv(1)=> Type=CallCtlConnDisconnectedEv Cause=CAUSE_BUSY ECldA=399 EClgA=769072241 CiscoCause=CAUSE_USERBUSY Cid=33620666 CCurCldA=399 CCurClgA=769072241 MetaCode(false)=META_CALL_ENDING Addr=399'
@16:12:59.6470 [((1] 1 49 ISISISIIBI 5 33620666 '399' 203 '' 17 '' 1 0 0 0
@16:12:59.6470 [tout] Collected jtapi[1] tevent(5:RELEASED)(399:) (20102ba:cb)  (:11).
@16:12:59.6470 [tout] CcmRouteParty::CcmEventReleased with cause cb OtherAddress: . State: IDLE
@16:12:59.6470 [gctmi] TMsg [EventReleased(399)] distributing to model
@16:12:59.6470 [gctmi] Call [027201e68cb2329e/20102ba,sOG,tOG,l1] distributing EventReleased
@16:12:59.6470 [gctmi] Call [027201e68cb2329e/20102ba,sOG,tOG,l1] processReleased
@16:12:59.6470 [gctm] Call [027201e68cb2329e/20102ba,sOG,tOG,l1] Generating regular release.
@16:12:59.6470 [gctmi] Party [027201e68cb2329e:399,s800,tRP,rDST,lINT] processReleased
@16:12:59.6470 [gctm] Party [027201e68cb2329e:399,s800,tRP,rDST,lINT] sending abandoned, not released
@16:12:59.6470 [gctm] Party [027201e68cb2329e:399,s800,tRP,rDST,lINT] Changing state to 0
@16:12:59.6470 [0] 8.0.001.01 distribute_event: message EventAbandoned
AttributeEventSequenceNumber 0000000000008989
AttributeTimeinuSecs 647000
AttributeTimeinSecs 1299852779 (16:12:59)
AttributeOtherDNRole 1
AttributeOtherDN '769072241'
AttributeThisDNRole 2
AttributeThisDN '399'
AttributeANI '769072241'
AttributeDNIS '399'
AttributeUserData [78] 00 04 00 00..
'Service' 'Customer'
'ACCOUNT' '0007300219'
'Company' 'SC TENET SRL'
'Accno' ''
AttributeCallUUID 'PE92V9KD5D7D98MLHVAN5710HS0001TJ'
AttributeConnID 027201e68cb2329e
AttributeCallID 33620666
AttributeCallType 2
AttributeThisQueue '399'
AttributeCallState 0
16:12:59.647 Int 04544 Interaction message "EventAbandoned" generated
16:12:59.647 Trc 04542 EventAbandoned sent to [668] (0000014d StatServerCCA_71 151.10.224.47:59954)
16:12:59.647 Trc 04542 EventAbandoned sent to [620] (0000014c StatServerCCA_71 151.10.224.47:59952)
16:12:59.647 Trc 04542 EventAbandoned sent to [584] (0000000b StatServer_Tz_EU-E 151.10.224.47:63138)
16:12:59.647 Trc 04542 EventAbandoned sent to [536] (00000007 StatServer_Tz_EU-E 151.10.224.47:63130)
16:12:59.647 Trc 04542 EventAbandoned sent to [548] (00000008 StatServerREP 151.10.224.47:63132)
16:12:59.647 Trc 04542 EventAbandoned sent to [524] (00000006 StatServerREP 151.10.224.47:63125)
16:12:59.647 Trc 04542 EventAbandoned sent to [512] (00000005 StatServerCCA_80 151.10.203.32:52959)
16:12:59.647 Trc 04542 EventAbandoned sent to [488] (00000003 StatServerCCA_80 151.10.203.32:52955)
16:12:59.647 Trc 04542 EventAbandoned sent to [500] (00000004 StatServerREP_80 151.10.203.32:52958)
16:12:59.647 Trc 04542 EventAbandoned sent to [448] (00000002 StatServerREP_80 151.10.203.32:52954)
16:12:59.647 Trc 04542 EventAbandoned sent to [608] (0000000d RO_StatServer_72 151.10.230.90:1191)
16:12:59.647 Trc 04542 EventAbandoned sent to [596] (0000000c RO_StatServer_72 151.10.230.90:1190)
16:12:59.647 Trc 04542 EventAbandoned sent to [560] (00000009 URServer_Tz_EU-E 151.10.224.47:63134)
@16:12:59.6470 [gctm] Call [027201e68cb2329e/20102ba,sOG,tOG,l0] Setting timer to 0M:30000mS
@16:12:59.6470 [gctm] Party [027201e68cb2329e:399,s0,tRP,rDST,lINT] deleting.
@16:12:59.6470 [gctm] Call [027201e68cb2329e/20102ba,sOG,t0M,l0] Changing state to 4
@16:12:59.6470 [gctm] Call [027201e68cb2329e/20102ba,sAB,t0M,l0] Setting timer to AB:2000mS
@16:12:59.6470 [sm] SmLegOwner destructor entered.
@16:12:59.6470 [sm] free_dcr_queue...
@16:12:59.6470 [sm]  dmx_stop_media_cmd, leg 3670
@16:12:59.6470 [sm] gw_stop_media_cmd: l:3670, MediaCmdActiveType 0, MediaStopActive 0, MediaCmdSent 0, MediaCmdIssuedType 0
@16:12:59.6470 [sm] SmLeg::Destroy for leg 3670, status 2
@16:12:59.6470 [tout] Total 1 legs on SM 1.
@16:12:59.6470 [tout] <<<<<Sending  SMEvent, s:468, n:'1 RO_VoIP_SM_760', e: DESTROY_LEG(leg=3670) ref=797
@16:12:59.6470 [tout] (CcmIntParty deleted)
@16:12:59.6470 [((1] 1 160 S 9 'CallEv(1)=> Type=CallInvalidEvent Cause=Other: 17 CiscoCause=CAUSE_USERBUSY Cid=33620666 CCurCldA=399 CCurClgA=769072241 MetaCode(false)=META_CALL_ENDING'
@16:12:59.6470 [((1] 1 21 ISI 8 33620666 '' 17
@16:12:59.6470 [tout] Collected jtapi[1] tevent(8:DELETE_CALL)( (20102ba:11)  (:0).
@16:12:59.6470 [((1] 1 163 S 9 'CallEv(1)=> Type=CallObservationEndedEv Cause=CAUSE_NORMAL CiscoCause=CAUSE_NOERROR Cid=33620666 CCurCldA=399 CCurClgA=769072241 MetaCode(true)=META_UNKNOWN'
@16:12:59.6620 [tout] >>>Incoming SMEvent, s:468, l:3670, n:'1 RO_VoIP_SM_760', e: DESTROY_LEG_ACK(id=1,err=0) ref=797
@16:13:01.6620 [gctm] Call [027201e68cb2329e/20102ba,sAB,tAB,l0] Abandon/Delete timer expired, cleaning up.
@16:13:01.6620 [tout] (~CcmCall)
@16:13:01.6620 [0] 8.0.001.01 distribute_event: message EventReleased
AttributeEventSequenceNumber 000000000000898a
AttributeTimeinuSecs 662000
AttributeTimeinSecs 1299852781 (16:13:01)
AttributeANI '769072241'
AttributeDNIS '399'
AttributeUserData [78] 00 04 00 00..
'Service' 'Customer'
'ACCOUNT' '0007300219'
'Company' 'SC TENET SRL'
'Accno' ''
AttributeCallUUID 'PE92V9KD5D7D98MLHVAN5710HS0001TJ'
AttributeConnID 027201e68cb2329e
AttributeCallID 33620666
AttributeCallType 2
AttributeThisDN 'RO_Slatina::'
16:13:01.662 Int 04544 Interaction message "EventReleased" generated
16:13:01.662 Trc 04542 EventReleased sent to [668] (0000014d StatServerCCA_71 151.10.224.47:59954)
16:13:01.662 Trc 04542 EventReleased sent to [620] (0000014c StatServerCCA_71 151.10.224.47:59952)
16:13:01.662 Trc 04542 EventReleased sent to [548] (00000008 StatServerREP 151.10.224.47:63132)
16:13:01.662 Trc 04542 EventReleased sent to [524] (00000006 StatServerREP 151.10.224.47:63125)
16:13:01.662 Trc 04542 EventReleased sent to [584] (0000000b StatServer_Tz_EU-E 151.10.224.47:63138)
16:13:01.662 Trc 04542 EventReleased sent to [536] (00000007 StatServer_Tz_EU-E 151.10.224.47:63130)
16:13:01.662 Trc 04542 EventReleased sent to [512] (00000005 StatServerCCA_80 151.10.203.32:52959)
16:13:01.662 Trc 04542 EventReleased sent to [488] (00000003 StatServerCCA_80 151.10.203.32:52955)
16:13:01.662 Trc 04542 EventReleased sent to [500] (00000004 StatServerREP_80 151.10.203.32:52958)
16:13:01.662 Trc 04542 EventReleased sent to [448] (00000002 StatServerREP_80 151.10.203.32:52954)
16:13:01.662 Trc 04542 EventReleased sent to [608] (0000000d RO_StatServer_72 151.10.230.90:1191)
16:13:01.662 Trc 04542 EventReleased sent to [596] (0000000c RO_StatServer_72 151.10.230.90:1190)
@16:13:01.6620 {tscp.call {destructed} {uuid PE92V9KD5D7D98MLHVAN5710HS0001TJ} {connection-id 027201e68cb2329e} {call-id 33620666}}
@16:13:01.6620 [gctm] Call [027201e68cb2329e/20102ba,sAB,tAB,l0] deleting.
@16:13:13.4280 [((1] 1 164 S 9 'CallEv(1)=> Type=CallActiveEvent Cause=CAUSE_NEW_CALL CiscoCause=CAUSE_NOERROR Cid=33620669 CCurCldA=399 CCurClgA=769072241 MetaCode(true)=META_CALL_STARTING'
@16:13:13.4280 [((1] 1 202 S 9 'CallEv(1)=> Type=ConnCreatedEvent Cause=CAUSE_NORMAL CiscoCause=CAUSE_NOERROR Cid=33620669 CCurCldA=399 CCurClgA=769072241 MetaCode(false)=META_CALL_STARTING Addr=399 ConnReason=REASON_DIRECTCALL'
@16:13:13.4280 [((1] 1 14 I 32 33620669
@16:13:13.4280 [tout] Collected jtapi[1] tevent(20:CREATE_CALL)( (20102bd:0)  (:0).
@16:13:13.4280 [((1] 1 176 S 9 'CallEv(1)=> Type=ConnInprogressEvent Cause=CAUSE_NORMAL CiscoCause=CAUSE_NOERROR Cid=33620669 CCurCldA=399 CCurClgA=769072241 MetaCode(false)=META_CALL_STARTING Addr=399'
@16:13:13.4280 [((1] 1 203 S 9 'CallEv(1)=> Type=CallCtlConnOfferedEv Cause=CAUSE_NORMAL ECldA=399 EClgA=769072241 CiscoCause=CAUSE_NOERROR Cid=33620669 CCurCldA=399 CCurClgA=769072241 MetaCode(false)=META_CALL_STARTING Addr=399'
@16:13:13.4280 [((1] 1 63 ISISIS 16 33620669 '399' 2 '769072241@S0/SU0/DS1-1@vg' 0 '399'
@16:13:13.4280 [tout] Collected jtapi[1] tevent(10:ROUTE_REQUEST)(399:769072241@S0/SU0/DS1-1@vg) (20102bd:2)  (399:0).
@16:13:13.4280 [tout] CcmSharedAddressResolver: Resolved 769072241@S0/SU0/DS1-1@vg -> 769072241 [Not in CME]
@16:13:13.4280 [gctmi] TMsg [EventRouteRequest(399)] distributing to model
@16:13:13.4280 {tscp.call {constructed} {uuid PE92V9KD5D7D98MLHVAN5710HS0001TL} {connection-id 027201e68cb2329f} {call-id 33620669}}
@16:13:13.4280 Call [027201e68cb2329f]: urid 00010272
@16:13:13.4280 [gctm] Call [027201e68cb2329f/20102bd,sST,tNO,l0] Setting timer to ST:2000mS
@16:13:13.4280 [gctm] Call [027201e68cb2329f/20102bd,sST,tST,l0] created.
@16:13:13.4280 [tout] Call [027201e68cb2329f/20102bd,sST,tST,l0] (CcmCall)[/sup]

Thanks.

[fnunezsa]

Please take a look at these 2 events and notice the 4 seconds difference.

16:12:55.631 Int 04544 Interaction message "EventRouteRequest" generated
@16:12:59.6470 [((1] 1 187 S 9 'CallEv(1)=> Type=ConnDisconnectedEvent Cause=Other: 17 CiscoCause=CAUSE_USERBUSY Cid=33620666 CCurCldA=399 CCurClgA=769072241

Those 4 seconds are the time that Cisco CM waits for TServer to provide a valid destination, so you should review you're strategy and URS logs to see why it is not retrieving one of your available agents.

Kind regards,
Franklin.

[alamitab]

[b]URS log:[/b]

[sup]received from 65202(--)app009ro:3000(fd=19) message EventRouteRequest
AttributeCallState 0
AttributeThisQueue '399'
AttributeCallType 2
AttributeCallID 33620666
AttributeConnID 027201e68cb2329e
attr_#141 'PE92V9KD5D7D98MLHVAN5710HS0001TJ'
AttributeDNIS '399'
AttributeANI '769072241'
AttributeThisDN '399'
AttributeThisDNRole 2
AttributeOtherDN '769072241'
AttributeOtherDNRole 1
AttributeTimeinSecs 1299852775 (15:12:55)
AttributeTimeinuSecs 631000
attr_#148 0000000000008986
Fri Mar 11 15:12:55 2011.786_T_I_0000000000000000 [14:0c] EventRouteRequest is received for tserver RO_TServer_CCM_800 (this dn=399)
    _C_W_027201e68cb2329e [0D:03] default value (0) will be used for option use_parking_threshold
    _C_W_027201e68cb2329e [0D:03] default value (3) will be used for option on_route_overlap
    _T_I_027201e68cb2329e [01:11] connid 027201e68cb2329e is bound to the call 185-80000001018e5c08
    _I_I_027201e68cb2329e [01:01] call (185-80000001018e5c08) for Resources created
    _T_I_027201e68cb2329e [14:09] add DN RO_TServer_CCM_800 399 <399@RO_Slatina> (CDN 71 027201e68cb2329e) to the call 185-80000001018e5c08 truly
    _T_I_027201e68cb2329e [14:08] check delayed proc
    _I_I_027201e68cb2329e [14:32] strategy: *0x65*RO_Slatina_V8 is attached to the call
    _C_W_027201e68cb2329e [0D:03] default value (0) will be used for option use_parking_threshold
Fri Mar 11 15:12:56 2011.058 Int 20001 interaction 027201e68cb2329e is started
Fri Mar 11 15:12:56 2011.063_I_I_027201e68cb2329e [09:06] >>>>>>>>>>>>start interpretator
    _I_I_027201e68cb2329e [09:04] ASSIGN: __Return(SCRIPT) <- STRING:
    _I_I_027201e68cb2329e [07:46] no error mode for this call
    _I_I_027201e68cb2329e [09:04] ASSIGN: __Return(SCRIPT) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: __DBReturn(SCRIPT) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: __DBStrReturn(SCRIPT) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: __TargetVar(SCRIPT) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: Var_StatServer(LOCAL) <- STRING: StatServer_Tz_EU-E
    _I_I_027201e68cb2329e [09:04] ASSIGN: Var_Country(LOCAL) <- STRING: RO
    _I_I_027201e68cb2329e [09:04] ASSIGN: Var_ServiceCalled(LOCAL) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: Var_HoldMusic(LOCAL) <- STRING: +announcement/202
    _I_I_027201e68cb2329e [09:04] ASSIGN: Var_Timeout(LOCAL) <- STRING: 120
    _I_I_027201e68cb2329e [09:04] ASSIGN: Var_Mailbox_Enabled(LOCAL) <- STRING: 0
    _I_I_027201e68cb2329e [09:04] ASSIGN: Var_Ani(LOCAL) <- STRING: 769072241
    _I_I_027201e68cb2329e [09:04] ASSIGN: Var_DNIS(LOCAL) <- STRING: 399
    _I_I_027201e68cb2329e [10:0d] HERE IS SDATA: RO--All_Agents2@StatServer_Tz_EU-E - StatAgentsLoggedin
Fri Mar 11 15:12:56 2011.735_M_I_ [10:06] tenant Resources GroupAgents <RO--All_Agents2>: statistic StatAgentsLoggedin with server StatServer_Tz_EU-E <request=1, status=2> asked
    _I_I_027201e68cb2329e [10:0d] sdata returns 3(S)
  result of SData: FLOAT: 3.000000
    _I_I_027201e68cb2329e [09:04] ASSIGN: Var_Agents_Logged(LOCAL) <- INTEGER: 3
    _I_I_027201e68cb2329e [09:04] ASSIGN: Var_Service(LOCAL) <- STRING: Customer
    _I_I_027201e68cb2329e [09:04] ASSIGN: Virtual_Queue(LOCAL) <- STRING: VQ_RO_Customers
    _I_I_027201e68cb2329e [09:04] ASSIGN: v_Skill(LOCAL) <- STRING: RO_Customer
request to 65202(--) message RequestUpdateUserData
AttributeReferenceID 738
AttributeUserData [22] 00 01 00 00..
'Service' 'Customer'
AttributeConnID 027201e68cb2329e
AttributeThisDN '399'
..sent to app009ro:3000(fd=19)
Fri Mar 11 15:12:56 2011.765_I_I_027201e68cb2329e [07:38] HERE IS XDATA
    _D_I_ [07:38] request 436 to dbserver DBServer_Customer sent: SELECT ADR2.AddrNumber FROM ADR2 WHERE ADR2.Tel_Number='769072241' AND ADR2.Client='210' ORDER BY ADR2.AddrNumber
Fri Mar 11 15:12:56 2011.805_I_I_027201e68cb2329e [09:04] <<<<<<<<<<<<suspend interpretator(XDATA_EX), timers:00000
Fri Mar 11 15:12:56 2011.805_M_I_ [10:1d] PULSE (calls: 1(1)=1+1-1, targets=0, time=1299852776, mem=0,133238,3641,7,193,0)
received from 65202(--)app009ro:3000(fd=19) message EventAttachedDataChanged
AttributeCallType 2
AttributeCallID 33620666
AttributeConnID 027201e68cb2329e
attr_#141 'PE92V9KD5D7D98MLHVAN5710HS0001TJ'
AttributeUserData [22] 00 01 00 00..
'Service' 'Customer'
AttributeDNIS '399'
AttributeANI '769072241'
AttributeThisDN '399'
AttributeThisDNRole 2
AttributeThirdPartyDN '399'
AttributeReferenceID 738
AttributeTimeinSecs 1299852776 (15:12:56)
AttributeTimeinuSecs 772000
attr_#148 0000000000008987
    _T_I_027201e68cb2329e [14:32] EventAttachedDataChanged is received for tserver RO_TServer_CCM_800 (this dn=399)
Fri Mar 11 15:12:58 2011.014_M_I_ [10:1d] PULSE (calls: 1(1)=1+0-0, targets=0, time=1299852777, mem=0,133238,3641,7,193,0)
nMsgID = MSG_RETRIEVED; nServer = 1; nStatus = 1; nRequestID = 436; nProfileTime 1545 szSQLCmd = ''; pRecord = 0x2447eb0
  key ADDRNUMBER [String] value: "0101247940"
Fri Mar 11 15:12:58 2011.702_D_I_027201e68cb2329e [05:02] MSG_RETRIEVED(status success) is received from dbserver DBServer_Customer
nMsgID = MSG_RETRIEVED; nServer = 1; nStatus = -99; nRequestID = 436; nProfileTime 1708 szSQLCmd = ''; pRecord = 0x0
Fri Mar 11 15:12:58 2011.702_D_I_027201e68cb2329e [05:02] MSG_RETRIEVED(status nomore or empty) is received from dbserver DBServer_Customer
Fri Mar 11 15:12:58 2011.702_I_I_027201e68cb2329e [09:05] >>>>>>>>>>>>resume interpretator(0)
    _I_I_027201e68cb2329e [09:04] ASSIGN: __DBReturn(SCRIPT) <- STRING: 0101247940
    _I_I_027201e68cb2329e [09:04] ASSIGN: Var_AddrNumber(LOCAL) <- STRING: 0101247940
Fri Mar 11 15:12:58 2011.893_I_I_027201e68cb2329e [07:38] HERE IS XDATA
    _D_I_ [07:38] request 437 to dbserver DBServer_Customer sent: SELECT KNA1.KUNNR,KNA1.NAME1 FROM KNA1 WHERE KNA1.ADRNR='0101247940' AND KNA1.MANDT='210' ORDER BY KNA1.KUNNR DESC
Fri Mar 11 15:12:58 2011.893_I_I_027201e68cb2329e [09:04] <<<<<<<<<<<<suspend interpretator(XDATA_EX), timers:00000
nMsgID = MSG_RETRIEVED; nServer = 1; nStatus = 1; nRequestID = 437; nProfileTime 223 szSQLCmd = ''; pRecord = 0x230a7c8
  key KUNNR [String] value: "0007300219"
  key NAME1 [String] value: "SC TENET SRL"
Fri Mar 11 15:12:59 2011.152_D_I_027201e68cb2329e [05:02] MSG_RETRIEVED(status success) is received from dbserver DBServer_Customer
nMsgID = MSG_RETRIEVED; nServer = 1; nStatus = -99; nRequestID = 437; nProfileTime 231 szSQLCmd = ''; pRecord = 0x0
Fri Mar 11 15:12:59 2011.153_D_I_027201e68cb2329e [05:02] MSG_RETRIEVED(status nomore or empty) is received from dbserver DBServer_Customer
Fri Mar 11 15:12:59 2011.153_I_I_027201e68cb2329e [09:05] >>>>>>>>>>>>resume interpretator(0)
    _I_I_027201e68cb2329e [09:04] ASSIGN: __DBReturn(SCRIPT) <- STRING: 0007300219,SC TENET SRL
    _I_I_027201e68cb2329e [09:04] ASSIGN: __DBStrReturn(SCRIPT) <- STRING: 0007300219
    _I_I_027201e68cb2329e [09:04] ASSIGN: __DBStrReturn(SCRIPT) <- STRING: SC TENET SRL
    _I_I_027201e68cb2329e [09:04] ASSIGN: __DBStrReturn(SCRIPT) <- STRING:
request to 65202(--) message RequestUpdateUserData
AttributeReferenceID 739
AttributeUserData [58] 00 03 00 00..
'ACCOUNT' '0007300219'
'Company' 'SC TENET SRL'
'Accno' ''
AttributeConnID 027201e68cb2329e
AttributeThisDN '399'
..sent to app009ro:3000(fd=19)
    _I_I_027201e68cb2329e [09:04] ASSIGN: Var_Account(LOCAL) <- STRING: 0007300219
Fri Mar 11 15:12:59 2011.154_I_I_027201e68cb2329e [07:38] HERE IS XDATA
    _D_I_ [07:38] request 438 to dbserver DBServer_Customer sent: SELECT KNVV.ZZSTP FROM KNVV WHERE KNVV.KUNNR='0007300219' AND KNVV.MANDT='210' ORDER BY KNVV.KUNNR
Fri Mar 11 15:12:59 2011.154_I_I_027201e68cb2329e [09:04] <<<<<<<<<<<<suspend interpretator(XDATA_EX), timers:00000
received from 65202(--)app009ro:3000(fd=19) message EventAttachedDataChanged
AttributeCallType 2
AttributeCallID 33620666
AttributeConnID 027201e68cb2329e
attr_#141 'PE92V9KD5D7D98MLHVAN5710HS0001TJ'
AttributeUserData [78] 00 04 00 00..
'Service' 'Customer'
'ACCOUNT' '0007300219'
'Company' 'SC TENET SRL'
'Accno' ''
AttributeDNIS '399'
AttributeANI '769072241'
AttributeThisDN '399'
AttributeThisDNRole 2
AttributeThirdPartyDN '399'
AttributeReferenceID 739
AttributeTimeinSecs 1299852779 (15:12:59)
AttributeTimeinuSecs 116000
attr_#148 0000000000008988
    _T_I_027201e68cb2329e [14:32] EventAttachedDataChanged is received for tserver RO_TServer_CCM_800 (this dn=399)
received from 65202(--)app009ro:3000(fd=19) message EventAbandoned
AttributeCallState 0
AttributeThisQueue '399'
AttributeCallType 2
AttributeCallID 33620666
AttributeConnID 027201e68cb2329e
attr_#141 'PE92V9KD5D7D98MLHVAN5710HS0001TJ'
AttributeUserData [78] 00 04 00 00..
'Service' 'Customer'
'ACCOUNT' '0007300219'
'Company' 'SC TENET SRL'
'Accno' ''
AttributeDNIS '399'
AttributeANI '769072241'
AttributeThisDN '399'
AttributeThisDNRole 2
AttributeOtherDN '769072241'
AttributeOtherDNRole 1
AttributeTimeinSecs 1299852779 (15:12:59)
AttributeTimeinuSecs 647000
attr_#148 0000000000008989
Fri Mar 11 15:12:59 2011.720_T_W_027201e68cb2329e [14:32] EventAbandoned is received for tserver RO_TServer_CCM_800 (this dn=399), delete call
Fri Mar 11 15:12:59 2011.846_I_I_027201e68cb2329e [07:48] suspend function
    _I_I_027201e68cb2329e [01:08] call deleting RO_AbandonedCall
Fri Mar 11 15:12:59 2011.846_I_I_027201e68cb2329e [07:49] resume function
    _I_I_027201e68cb2329e [07:42] jump to strategy *0x65*RO_AbandonedCall
Fri Mar 11 15:12:59 2011.847_I_I_027201e68cb2329e [09:06] >>>>>>>>>>>>start interpretator
    _I_I_027201e68cb2329e [09:04] ASSIGN: __Return(SCRIPT) <- STRING:
    _I_I_027201e68cb2329e [07:46] no error mode for this call
    _I_I_027201e68cb2329e [09:04] ASSIGN: __Return(SCRIPT) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: __DBReturn(SCRIPT) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: __DBStrReturn(SCRIPT) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: __TargetVar(SCRIPT) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: Var_GruppoCode(LOCAL) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: v_Country(LOCAL) <- STRING: RO
    _I_I_027201e68cb2329e [09:04] ASSIGN: v_DNIS(LOCAL) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: v_ANI(LOCAL) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: v_SvcType(LOCAL) <- STRING: Customer
    _I_I_027201e68cb2329e [09:04] ASSIGN: v_CRMSub(LOCAL) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: v_CustName(LOCAL) <- STRING: SC TENET SRL
    _I_I_027201e68cb2329e [09:04] ASSIGN: Var_Account(LOCAL) <- STRING: 0007300219
    _I_I_027201e68cb2329e [09:04] ASSIGN: v_IVROpts(LOCAL) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: v_ScriptRef(LOCAL) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: v_Progress(LOCAL) <- STRING:
Fri Mar 11 15:12:59 2011.912_I_I_027201e68cb2329e [07:48] suspend function
Fri Mar 11 15:12:59 2011.913_I_I_027201e68cb2329e [09:04] <<<<<<<<<<<<suspend interpretator(JUMPING), timers:00001
Fri Mar 11 15:12:59 2011.918_I_I_027201e68cb2329e [07:49] resume function
    _I_I_027201e68cb2329e [07:43] call strategy *0x65*AbandonedCallExtended_V3
Fri Mar 11 15:12:59 2011.918_I_I_027201e68cb2329e [09:06] >>>>>>>>>>>>start interpretator
    _I_I_027201e68cb2329e [07:46] no error mode for this call
    _I_I_027201e68cb2329e [09:04] ASSIGN: __Return(SCRIPT) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: __DBReturn(SCRIPT) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: __DBStrReturn(SCRIPT) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: __TargetVar(SCRIPT) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: v_Progr(LOCAL) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: v_CustName(LOCAL) <- STRING: SC TENET SRL
    _I_I_027201e68cb2329e [09:04] ASSIGN: v_ServiceType(LOCAL) <- STRING: Customer
    _I_I_027201e68cb2329e [09:04] ASSIGN: v_ScriptRef(LOCAL) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: v_IVROpts(LOCAL) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: v_DNIS(LOCAL) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: v_CustANI(LOCAL) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: v_CRMSubType(LOCAL) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: v_Country(LOCAL) <- STRING: RO
    _I_I_027201e68cb2329e [09:04] ASSIGN: v_AccNum(LOCAL) <- STRING: 0007300219
    _I_I_027201e68cb2329e [09:04] ASSIGN: Country(LOCAL) <- STRING: RO
    _I_I_027201e68cb2329e [09:04] ASSIGN: AccNum(LOCAL) <- STRING: 0007300219
    _I_I_027201e68cb2329e [09:04] ASSIGN: CustANI(LOCAL) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: CustANI(LOCAL) <- STRING: .
    _I_I_027201e68cb2329e [09:04] ASSIGN: CRMSubType(LOCAL) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: CRMSubType(LOCAL) <- STRING: .
    _I_I_027201e68cb2329e [09:04] ASSIGN: CustDNIS(LOCAL) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: CustDNIS(LOCAL) <- STRING: .
    _I_I_027201e68cb2329e [09:04] ASSIGN: CustName(LOCAL) <- STRING: SC TENET SRL
    _I_I_027201e68cb2329e [09:04] ASSIGN: IVROpts(LOCAL) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: IVROpts(LOCAL) <- STRING: .
    _I_I_027201e68cb2329e [09:04] ASSIGN: ScriptRef(LOCAL) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: ScriptRef(LOCAL) <- STRING: .
    _I_I_027201e68cb2329e [09:04] ASSIGN: SvcType(LOCAL) <- STRING: Customer
    _I_I_027201e68cb2329e [09:04] ASSIGN: Progress(LOCAL) <- STRING:
    _I_I_027201e68cb2329e [09:04] ASSIGN: Progress(LOCAL) <- STRING: .
Fri Mar 11 15:12:59 2011.969_I_I_027201e68cb2329e [07:38] HERE IS XDATA
    _D_I_ [07:38] request 439 to dbserver DBServerOCS71 sent: CREATE_ABAND_CALL_EXT P_ACCNUM='0007300219',P_COMPANY='SC TENET SRL',P_COUNTRY='RO',P_CRMSUBTYPE='.',P_CUSTANI='.',P_DNIS='.',P_IVROPTS='.',P_PRG='.',P_RECORDID=@out,P_SCRIPTREF='.',P_SERVICETYPE='Customer'
Fri Mar 11 15:13:00 2011.011_I_I_027201e68cb2329e [09:04] <<<<<<<<<<<<suspend interpretator(XDATA_EX), timers:00000
nMsgID = MSG_ERROR; nServer = 1; nStatus = 14; nRequestID = 612; nProfileTime 0 szSQLCmd = ''; pRecord = 0x0
Fri Mar 11 15:13:00 2011.011_M_I_ [10:1d] PULSE (calls: 1(1)=1+0-0, targets=0, time=1299852779, mem=0,133204,3642,7,193,0)
nMsgID = MSG_RETRIEVED; nServer = 0; nStatus = 1; nRequestID = 439; nProfileTime 16 szSQLCmd = 'SP Params'; pRecord = 0x22b2978
  key P_RECORDID [String] value: "35215"
Fri Mar 11 15:13:00 2011.039_D_I_027201e68cb2329e [05:02] MSG_RETRIEVED(status success) is received from dbserver DBServerOCS71
nMsgID = MSG_PROCCOMPLETED; nServer = 0; nStatus = 1; nRequestID = 439; nProfileTime 16 szSQLCmd = ''; pRecord = 0x0
Fri Mar 11 15:13:00 2011.039_D_I_027201e68cb2329e [05:02] MSG_PROCCOMPLETED (status 1) is received from dbserver DBServerOCS71
Fri Mar 11 15:13:00 2011.039_I_I_027201e68cb2329e [09:05] >>>>>>>>>>>>resume interpretator(0)
    _I_I_027201e68cb2329e [09:04] ASSIGN: __DBReturn(SCRIPT) <- STRING: 35215
    _I_I_027201e68cb2329e [09:04] ASSIGN: RecID(LOCAL) <- STRING: 35215
    _I_I_027201e68cb2329e [09:04] ASSIGN: v_RecordID(LOCAL) <- STRING: 35215
Fri Mar 11 15:13:00 2011.039_I_I_027201e68cb2329e [07:48] suspend function
Fri Mar 11 15:13:00 2011.039_I_I_027201e68cb2329e [09:04] <<<<<<<<<<<<suspend interpretator(JUMPING), timers:00001
Fri Mar 11 15:13:00 2011.039_I_I_027201e68cb2329e [07:49] resume function
    _I_I_027201e68cb2329e [07:44] jump to strategy *0x65*RO_AbandonedCall
Fri Mar 11 15:13:00 2011.040_I_I_027201e68cb2329e [09:05] >>>>>>>>>>>>resume interpretator(0)
    _I_I_027201e68cb2329e [09:04] ASSIGN: v_RecordID(LOCAL) <- STRING: 35215
    _I_I_027201e68cb2329e [09:04] OP_XCALL_NO_RESULT: function Default returns INTERP_STOP, go to stop handling
    _I_I_027201e68cb2329e [01:0a] <<<<<<<<<<<<stop interpretator
    _I_I_027201e68cb2329e [01:08] call deleting truly
CALL (027201e68cb2329e) HISTORY ( Abandon ):
Fri Mar 11 15:13:00 2011.040 Int 20005 interaction 027201e68cb2329e is abandoned
nMsgID = MSG_RETRIEVED; nServer = 1; nStatus = 1; nRequestID = 438; nProfileTime 476 szSQLCmd = ''; pRecord = 0x2448068
  key ZZSTP [String] value: "RF5"
nMsgID = MSG_RETRIEVED; nServer = 1; nStatus = 1; nRequestID = 438; nProfileTime 476 szSQLCmd = ''; pRecord = 0x2448068
  key ZZSTP [String] value: "RF5"
nMsgID = MSG_RETRIEVED; nServer = 1; nStatus = 1; nRequestID = 438; nProfileTime 476 szSQLCmd = ''; pRecord = 0x2448068
  key ZZSTP [String] value: "RF5"
nMsgID = MSG_RETRIEVED; nServer = 1; nStatus = 1; nRequestID = 438; nProfileTime 476 szSQLCmd = ''; pRecord = 0x2448068
  key ZZSTP [String] value: "RF5"
nMsgID = MSG_RETRIEVED; nServer = 1; nStatus = 1; nRequestID = 438; nProfileTime 476 szSQLCmd = ''; pRecord = 0x2448068
  key ZZSTP [String] value: "RFB"
nMsgID = MSG_RETRIEVED; nServer = 1; nStatus = 1; nRequestID = 438; nProfileTime 476 szSQLCmd = ''; pRecord = 0x2448068
  key ZZSTP [String] value: "RF5"
nMsgID = MSG_RETRIEVED; nServer = 1; nStatus = -99; nRequestID = 438; nProfileTime 480 szSQLCmd = ''; pRecord = 0x0[/sup]

[fnunezsa]

If you take a look at the provided log you'll notice this:

At 16:12:55 URS get the EventRouteRequest
At 15:12:56 Your strategy executes a DB dip
At 15:12:58 Your strategy gets the response from the DB
At 15:12:58 Your strategy executes another DB dip
At 15:12:59 Your strategy gets the response from the DB for the second DB DIP. At this time the 4 seconds window from Cisco has expired 
At 15:12:59 Your strategy executes another DB dip
At 15:12:59 TServer gets EventAbandoned messsage from Cisco and distribute it to its clients

I'd suggest to:
1) Review your strategy as I don't believe that a strategy should take up to 4 seconds to retrieve a target. Maybe you're doing extra stuff that you don't really needs.
2) Review you're DB dips. Maybe you need some indexes in your tables to get those select statements to perform better. Usually having those select defined as stored procedure helps improving performance as the statements are already compiled when you invoke you're stored procedure, but your selects have to be compiled eveytime you execute them.

HTH.