Genesys CTI User Forum
Genesys CTI User Forum => Genesys CTI Technical Discussion => Topic started by: pspenning on March 18, 2014, 12:14:56 PM
-
Good Day Everyone,
I am seeing something in our URS logs that I a little strange to me. Usually, when URS polls the stat server for Agent availablility, I see the stat server reply with the status of the agent (Logged Out, ReadyForNextCall, Etc.) I am looking at a call now where this isn't the case. It doesn't give the detail. It just states that it asked the stat server and then it puts the call in the queue. This particular call sat in queue for over an hour. Would this be an instance where the URS stat server never responded? I looked in the URS stat server logs but really couldn't make much of it. Here is the snippet from the URS server.
[code]18:07:10.022_I_I_020902408889717f [07:07] HERE IS TARGETS
TARGETS: ?:US >= 5 & English >= 5 & Sabre >= 5 & Stryker >= 5 & (VIP >= 5 | Help >= 5)@.GA
18:07:10.022_M_I_ [17:0c] VQ 2b1af6c562c0 created: type=0, ten=Resources
===============================
_M_I_ [17:06] VQ 2b1af6c562c0 TRG 2b1af6bd1e80 added: name=?:US >= 5 & English >= 5 & Sabre >= 5 & Stryker >= 5 & (VIP >= 5 | Help >= 5), location=ATL_URS_Stat_Server_Pri, type=GA, state=##state, activity=unknown
18:07:10.022_M_I_ [10:06] SO(2b1af67c23e0 -1 2) ten=Resources name=?:US >= 5 & English >= 5 & Sabre >= 5 & Stryker >= 5 & (VIP >= 5 | Help >= 5)@ATL_URS_Stat_Server_Pri.GA: stat <##content> asked (t=0 f=0)
18:07:10.022_M_I_ [17:05] VQ 2b1af6c562c0 TRG 2b1af6bd1e80 (name=?:US >= 5 & English >= 5 & Sabre >= 5 & Stryker >= 5 & (VIP >= 5 | Help >= 5), location=ATL_URS_Stat_Server_Pri, type=GA) synchronizing (o=0, n=6, c=0)
18:07:10.022_M_I_ [10:5d] SO(133b09b0 10732 2) ten=Resources name=048720@ATL_URS_Stat_Server_Pri.A: stat <##state> asked (t=0 f=0)
_M_I_ [17:09] VQ 2b1af6c562c0 TRG "?:US >= 5 & English >= 5 & Sabre >= 5 & Stryker >= 5 & (VIP >= 5 | Help >= 5)"(2b1af6bd1e80): connected to state Agent 048720 ##state(133b09b0)
18:07:10.022_M_I_ [10:5d] SO(1302c890 5155 2) ten=Resources name=052050@ATL_URS_Stat_Server_Pri.A: stat <##state> asked (t=0 f=0)
_M_I_ [17:09] VQ 2b1af6c562c0 TRG "?:US >= 5 & English >= 5 & Sabre >= 5 & Stryker >= 5 & (VIP >= 5 | Help >= 5)"(2b1af6bd1e80): connected to state Agent 052050 ##state(1302c890)
18:07:10.022_M_I_ [10:5d] SO(130b36e0 5951 2) ten=Resources name=117752@ATL_URS_Stat_Server_Pri.A: stat <##state> asked (t=0 f=0)
_M_I_ [17:09] VQ 2b1af6c562c0 TRG "?:US >= 5 & English >= 5 & Sabre >= 5 & Stryker >= 5 & (VIP >= 5 | Help >= 5)"(2b1af6bd1e80): connected to state Agent 117752 ##state(130b36e0)
18:07:10.022_M_I_ [10:5d] SO(2b1af459d7f0 13921 2) ten=Resources name=115849@ATL_URS_Stat_Server_Pri.A: stat <##state> asked (t=0 f=0)
_M_I_ [17:09] VQ 2b1af6c562c0 TRG "?:US >= 5 & English >= 5 & Sabre >= 5 & Stryker >= 5 & (VIP >= 5 | Help >= 5)"(2b1af6bd1e80): connected to state Agent 115849 ##state(2b1af459d7f0)
18:07:10.022_M_I_ [10:5d] SO(2b1af4629530 14262 2) ten=Resources name=114207@ATL_URS_Stat_Server_Pri.A: stat <##state> asked (t=0 f=0)
_M_I_ [17:09] VQ 2b1af6c562c0 TRG "?:US >= 5 & English >= 5 & Sabre >= 5 & Stryker >= 5 & (VIP >= 5 | Help >= 5)"(2b1af6bd1e80): connected to state Agent 114207 ##state(2b1af4629530)
18:07:10.022_M_I_ [10:5d] SO(1309c3e0 5800 2) ten=Resources name=115864@ATL_URS_Stat_Server_Pri.A: stat <##state> asked (t=0 f=0)
_M_I_ [17:09] VQ 2b1af6c562c0 TRG "?:US >= 5 & English >= 5 & Sabre >= 5 & Stryker >= 5 & (VIP >= 5 | Help >= 5)"(2b1af6bd1e80): connected to state Agent 115864 ##state(1309c3e0)
18:07:10.022_M_I_ [10:06] SO(12e8c880 2443 2) ten=Resources name=048720@ATL_URS_Stat_Server_Pri.A: stat <StatTimeInReadyState> asked (t=0 f=0)
18:07:10.022_M_I_ [10:06] SO(13307210 9732 2) ten=Resources name=052050@ATL_URS_Stat_Server_Pri.A: stat <StatTimeInReadyState> asked (t=0 f=0)
18:07:10.022_M_I_ [10:06] SO(133a65c0 10652 2) ten=Resources name=117752@ATL_URS_Stat_Server_Pri.A: stat <StatTimeInReadyState> asked (t=0 f=0)
18:07:10.022_M_I_ [10:06] SO(2b1af4599350 13922 2) ten=Resources name=115849@ATL_URS_Stat_Server_Pri.A: stat <StatTimeInReadyState> asked (t=0 f=0)
18:07:10.022_M_I_ [10:06] SO(2b1af4627220 14263 2) ten=Resources name=114207@ATL_URS_Stat_Server_Pri.A: stat <StatTimeInReadyState> asked (t=0 f=0)
18:07:10.022_M_I_ [10:06] SO(133859d0 10469 2) ten=Resources name=115864@ATL_URS_Stat_Server_Pri.A: stat <StatTimeInReadyState> asked (t=0 f=0)
18:07:10.022_T_I_020902408889717f [14:02] sending event 57 for vq STRYKER_VIP_US_EN_IN_V_VQ (0 0 1 1394222852 1187 37)
request to 65208(ATL_SIP_VQ_Pri/KSC_SIP_VQ_Bac) message RequestDistributeEvent
AttributeCallUUID '00MIR5N9489GTE913C0I62LAES00C0F2'
AttributeTimeout 60
AttributeTimeinuSecs 22000
AttributeTimeinSecs 1394237230 (18:07:10)
AttributeExtensions [205] 00 07 00 00..
'SIGNATURE' 'router'
'NAME' 'ATL_URS_Pri'
'VERSION' 'Version: 8.1.300.23'
'CLUSTER' 'ATL_URS_Pri'
'VQID' '01G3QJNIMS9GT5RT4O0I62LAES005ORS'
'Location' 'Atlanta GA'
'CallUUID' '00MIR5N9489GTE913C0I62LAES00C0F2'
AttributeUserData [476] 00 12 00 00..
'From' '<sip:4085504611@10.35.8.37>;tag=snl_PceI9aqf3T'
'Call-ID' 'SEC11-508230a-532020a-1-52RIcZ7L71Rd'
'SDP:o' '- 1404393278 1404393278 IN IP4 10.35.8.41'
'OrigDNIS' '18668261929'
'StatServer' 'ATL_URS_Stat_Server_Pri'
'Vmail' '0'
'CustomerID' 'Stryker'
'Client Name' 'Stryker'
'Service' 'Stryker'
'GDS' 'Sabre'
'PCC' 'XXXX'
'OrganizationalID' ''
'Record_Locator' ''
'OrigLoc' ''
'Language' 'English'
'Default_RP' '12695533203'
'Call Type' 'VIP'
'Virtual Queue' 'STRYKER_VIP_US_EN_IN_V_VQ'
AttributeANI '4085504611'
AttributeDNIS '18668261929'
AttributeOtherDNRole 1
AttributeOtherDN '4085504611'
AttributeThisDNRole 2
AttributeThisQueue 'STRYKER_VIP_US_EN_IN_V_VQ'
AttributeThisDN 'STRYKER_VIP_US_EN_IN_V_VQ'
AttributeCallType 2
AttributeCallID 4528983
AttributeConnID 020902408889717f
AttributeCustomerID 'Resources'
AttributeReferenceID 4294967295
AttributeUserEvent EventQueued
..sent to usgadtc5gen01:3000(fd=19)
18:07:10.022 RLIB: request to 24(KSC_URS_Bac) message VirtualQueue(1000000202)
callid(1000000000) 020902408889717f
data0(1000000200) 18892
data1(1000000201) 57
data3(1000000203) 'Resources'
data4(1000000204) '01G3QJNIMS9GT5RT4O0I62LAES005ORS'
18:07:10.022_M_I_020902408889717f [13:02] entering vq "STRYKER_VIP_US_EN_IN_V_VQ"
_M_I_020902408889717f [17:0f] VQ 2b1af6c562c0 [at all 65 0 0] 1 Target(s), flag=2b1a0000808a, guid: 0Resources|STRYKER_VIP_US_EN_IN_V_VQ|1|d-1|1|00||||||01StatTimeInReadyState|00{}{}{}[]?:US >= 5 & English >= 5 & Sabre >= 5 & Stryker >= 5 & (VIP >= 5 | Help >= 5)@ATL_URS_Stat_Server_Pri.GA
18:07:10.022_M_I_020902408889717f [13:01] current vq: 2b1af5c6c730 id=513207(), nVQ=30-2b1af6c04b40, priority=10, time=1394237230.22
18:07:10.022_M_I_020902408889717f [17:11] VQ 2b1af6c562c0 first available call: 020902408889717f, reason=(1)binding
18:07:10.022_M_I_020902408889717f [13:03] call (vq 2b1af5c6c730, id=513207, priority 10, time 1394237230.22) waits for VQ 2b1af6c562c0 (name="STRYKER_VIP_US_EN_IN_V_VQ") now (0)
request to 65202(--/KSC_SipServer_Bac) message RequestUpdateUserData
AttributeReferenceID 8500142
AttributeUserData [144] 00 02 00 00..
'RTargetAgentGroup' '?:US >= 5 & English >= 5 & Sabre >= 5 & Stryker >= 5 & (VIP >= 5 | Help >= 5)'
'RPVQID' '01G3QJNIMS9GT5RT4O0I62LAES005ORS'
AttributeConnID 020902408889717f
AttributeThisDN '18668261929'
..sent to usgadtc5gen03:3000(fd=17)
18:07:10.022_T_I_020902408889717f [14:02] sending event 85 for vq STRYKER_VIP_US_EN_IN_V_VQ (0 0 1 1394222852 1187 37)
request to 65208(ATL_SIP_VQ_Pri/KSC_SIP_VQ_Bac) message RequestDistributeEvent
AttributeCallUUID '00MIR5N9489GTE913C0I62LAES00C0F2'
AttributeTimeout 60
AttributeTimeinuSecs 22000
AttributeTimeinSecs 1394237230 (18:07:10)
AttributeExtensions [205] 00 07 00 00..
'SIGNATURE' 'router'
'NAME' 'ATL_URS_Pri'
'VERSION' 'Version: 8.1.300.23'
'CLUSTER' 'ATL_URS_Pri'
'VQID' '01G3QJNIMS9GT5RT4O0I62LAES005ORS'
'Location' 'Atlanta GA'
'CallUUID' '00MIR5N9489GTE913C0I62LAES00C0F2'
AttributeUserData [618] 00 14 00 00..
'From' '<sip:4085504611@10.35.8.37>;tag=snl_PceI9aqf3T'
'Call-ID' 'SEC11-508230a-532020a-1-52RIcZ7L71Rd'
'SDP:o' '- 1404393278 1404393278 IN IP4 10.35.8.41'
'OrigDNIS' '18668261929'
'StatServer' 'ATL_URS_Stat_Server_Pri'
'Vmail' '0'
'CustomerID' 'Stryker'
'Client Name' 'Stryker'
'Service' 'Stryker'
'GDS' 'Sabre'
'PCC' '7HLA'
'OrganizationalID' ''
'Record_Locator' ''
'OrigLoc' ''
'Language' 'English'
'Default_RP' '12695533203'
'Call Type' 'VIP'
'Virtual Queue' 'STRYKER_VIP_US_EN_IN_V_VQ'
'RTargetAgentGroup' '?:US >= 5 & English >= 5 & Sabre >= 5 & Stryker >= 5 & (VIP >= 5 | Help >= 5)'
'RPVQID' '01G3QJNIMS9GT5RT4O0I62LAES005ORS'
AttributeANI '4085504611'
AttributeDNIS '18668261929'
AttributeOtherDNRole 1
AttributeOtherDN '4085504611'
AttributeThisDNRole 2
AttributeThisQueue 'STRYKER_VIP_US_EN_IN_V_VQ'
AttributeThisDN 'STRYKER_VIP_US_EN_IN_V_VQ'
AttributeCallType 2
AttributeCallID 4528983
AttributeConnID 020902408889717f
AttributeCustomerID 'Resources'
AttributeReferenceID 4294967295
AttributeUserEvent EventAttachedDataChanged
..sent to usgadtc5gen01:3000(fd=19)
18:07:10.022_M_I_020902408889717f [17:0e] VQ 2b1af6c562c0 (vq "STRYKER_VIP_US_EN_IN_V_VQ", id=513207), (1 Targets): SELECT MAX by stat <StatTimeInReadyState>(random 0)
_M_I_020902408889717f [17:0e] VQ 2b1af6c562c0 TRG "?:US >= 5 & English >= 5 & Sabre >= 5 & Stryker >= 5 & (VIP >= 5 | Help >= 5)"(2b1af6bd1e80): empty(6-6 components) passed
_M_I_020902408889717f [17:0e] VQ 2b1af6c562c0 (vq "STRYKER_VIP_US_EN_IN_V_VQ" id=513207): TRG NOT SELECTED (0 1 0 0 0)
_I_I_020902408889717f [07:0a] HERE IS WAIT (-1 sec)
_I_I_020902408889717f [07:0a] HERE IS WAIT (10 sec)
18:07:10.022_B_I_020902408889717f [07:0a] delay treatments for 200 msec
18:07:10.022_I_I_020902408889717f [09:04] <<<<<<<<<<<<suspend interp(WAIT), func:Wait timers:11000
received from 65208(KSC_SIP_VQ_Bac)usmoksc5app02:3000(fd=) message EventACK(refid=-1)
received from 65208(KSC_SIP_VQ_Bac)usmoksc5app02:3000(fd=) message EventACK(refid=-1)
received from 65202(ATL_SipServer_Pri)usgadtc5gen03:3000(fd=) message EventAttachedDataChanged(refid=8500140)
18:07:10.023_T_I_020902408889717f [14:32] EventAttachedDataChanged is received for ts ATL_SipServer_Pri[Atlanta GA] (this dn=18668261929, refid=8500140)
received from 65202(ATL_SipServer_Pri)usgadtc5gen03:3000(fd=) message EventAttachedDataChanged(refid=8500141)
18:07:10.023_T_I_020902408889717f [14:32] EventAttachedDataChanged is received for ts ATL_SipServer_Pri[Atlanta GA] (this dn=18668261929, refid=8500141)
received from 65202(ATL_SipServer_Pri)usgadtc5gen03:3000(fd=) message EventAttachedDataChanged(refid=8500142)
18:07:10.023_T_I_020902408889717f [14:32] EventAttachedDataChanged is received for ts ATL_SipServer_Pri[Atlanta GA] (this dn=18668261929, refid=8500142)
18:07:10.222_B_I_020902408889717f [07:64] start chain of treatments
_T_I_020902408889717f [14:27] treatment starting: type=Music, par1=MUSIC_DN:music/music.wav|, par2=##3511##, tout=10
_B_I_020902408889717f [14:26] treatment starting - ok
18:07:10.222_T_I_020902408889717f [14:25] TApplyTreatment (type Music) is being called[/code]
Something that stands out to me is where I would normally receive a reply from the stat server, I see:
[code] _I_I_020902408889717f [07:0a] HERE IS WAIT (-1 sec)
_I_I_020902408889717f [07:0a] HERE IS WAIT (10 sec)
[/code]
I don't understand why the HERE IS WAIT (-1 SEC) is there.
If anyone can help explain what I am missint, I would appreciate the help.
Thanks - Perry
-
Wait(-1) is irrelevant here - it is always present in the log. It just way IRD generate startegy code on behalf of Slection object - first Wait[-1] and a bit later Wait[real wauting time] (you can check yourself if look into generateted source code).
Provided log fragment is quite standard for case when URS create new "queue":
[b]18:07:10.022_M_I_ [17:0c] VQ 2b1af6c562c0 created: type=0, ten=Resources[/b]
The only things that is "missed" is attempt to find agent itself but reason of it is
_M_I_020902408889717f [17:0e] VQ 2b1af6c562c0 TRG "?:US >= 5 & English >= 5 & Sabre >= 5 & Stryker >= 5 & (VIP >= 5 | Help >= 5)"(2b1af6bd1e80):[b] empty(6-6 components) [/b] passed
which means that "queue" 2b1af6c562c0 has 6 agents and 6 of them are logged out (according to data URS get from statserver) making queue effectively empty at this moment of time so URS skips searching cycle at once.
Probably logs of others components (statserver, tserver) to be checked why agent are reported as logged out.
Thanks,
Terry
-
Wonderful... That explains the mystery! I really appreciate the information.
Have a great day.
Perry