Unexpected EventAgentReady

[alamitab]

Hi guys.

I have an unexpected EventAgentReady.
Could you tell me from these logs wich could be the cause ?
Switch: Alcatel A4400
TServer version 7.6

[sup]@16:25:52.9300 [0] 7.6.003.05 distribute_response: message EventAgentNotReady
AttributeExtensions [124] 00 03 00 00..
'GCTI_THIS_DEVICE_NAME' 'Agent1'
'GCTI_INFO_STR' 'manual wrap-up'
'AgentSessionID' '0V25V1C2MT2P18D38JG413O794007JN1'
AttributeEventSequenceNumber 000000000007da3b
AttributeCustomerID 'Resources'
AttributeTimeinuSecs 930000
AttributeTimeinSecs 1373466352 (16:25:52)
AttributeReason [21] 00 01 01 00..
'ReasonCode' 4
AttributeReferenceID 33134
AttributeAgentWorkMode 3 (AfterCallWork)
AttributeThisQueue '5830200'
AttributeAgentID '1844'
AttributeThisDN '844'
@16:25:52.9300 [ISCC] Translate: '' -> ''; result 1 ()
16:25:52.930 Trc 04542 EventAgentNotReady sent to [548] (00000009 GPlus_EU-West_b4 151.10.225.48:3458)
16:25:52.930 Trc 04542 EventAgentNotReady sent to [484] (0000000e StatServer80_Tz_EU-Wb 151.10.203.31:58077)
16:25:52.930 Trc 04542 EventAgentNotReady sent to [508] (00000006 FR_StatServer 151.10.96.47:2429)
16:25:52.930 Trc 04542 EventAgentNotReady sent to [472] (00000003 StatServerREP_80 151.10.203.31:58528)
16:25:52.930 Trc 04542 EventAgentNotReady sent to [452] (00000002 StatServerCCA_80 151.10.203.31:58527)
  context is reset

link (link-tcp) S->H: (0[0 / 0] requests pending)
07/10/13@16:26:28.867 RECEIVED: (12) bytes - System Status ('keep-alive' request)
@07/10/13@16:26:28.867 **** PBX::SystemStatus ****
link (link-tcp) S->H: System status request (id=6776 [2]) from PBX (0[0 / 0] requests pending)
@16:26:44.992 DataFromSwitch 56 bytes
0000-000f: a1 36 02 02 67 78 02 01-15 30 2d 55 04 01 7a c0 |.6..gx...0-U..z.|
0010-001f: 00 a2 12 a4 10 30 0e 63-06 84 04 31 38 34 34 04 |.....0.c...1844.|
0020-002f: 04 31 38 34 34 7e 11 a0-0f 17 0d 31 33 30 37 31 |.1844~.....13071|
0030-0037: 30 31 36 32 32 33 36 5a-                        |0162236Z        |
07/10/13@16:26:44.992 RECEIVED: 56 bytes
aPDU-rose invoke { -- SEQUENCE --
  invokeID 26488,
  operationValue 21,
  argument { -- SEQUENCE --
    crossRefIdentifier '017ac000'H  -- ".zÀ." --,
    eventSpecificInfo agentStateEvent readyEvent { -- SEQUENCE --
      agentDevice deviceIdentifier implicitPrivate '31383434'H  -- "1844" --,
      agentID '31383434'H  -- "1844" --
    },
    extensions { -- SEQUENCE --
      security { -- SEQUENCE --
        timeStamp '3133303731303136323233365a'H  -- "130710162236Z" --
      }
    }
  }
}
cstaSwitchingEventDecode: Ready event in progress
+++ Evt::Ready +++
  *** Transaction Info:
    Type/Oper. : 1 - 204 <Event : Ready>
    crossRef  : 17ac000
    LocalDev[0]: 1844 (Private)
    LocalDev[1]: 1844 (Unknown)
    TimeStamp  : <130710162236Z>
  refDev <1844> (cref = '17AC000')
@16:26:44.9920 [0] 7.6.003.05 distribute_event: message EventAgentReady
AttributeExtensions [53] 00 01 00 00..
'AgentSessionID' '0V25V1C2MT2P18D38JG413O794007JN1'
AttributeEventSequenceNumber 000000000007da3d
AttributeCustomerID 'Resources'
AttributeTimeinuSecs 992000
AttributeTimeinSecs 1373466404 (16:26:44)
AttributeAgentWorkMode 0 (Unknown)
AttributeThisQueue '5830200'
AttributeAgentID '1844'
AttributeThisDN '844'
@16:26:44.9920 [ISCC] Translate: '' -> ''; result 1 ()
16:26:44.992 Trc 04542 EventAgentReady sent to [484] (0000000e StatServer80_Tz_EU-Wb 151.10.203.31:58077)
16:26:44.992 Trc 04542 EventAgentReady sent to [548] (00000009 GPlus_EU-West_b4 151.10.225.48:3458)
16:26:44.992 Trc 04542 EventAgentReady sent to [508] (00000006 FR_StatServer 151.10.96.47:2429)
16:26:44.992 Trc 04542 EventAgentReady sent to [472] (00000003 StatServerREP_80 151.10.203.31:58528)
16:26:44.992 Trc 04542 EventAgentReady sent to [452] (00000002 StatServerCCA_80 151.10.203.31:58527)
--- Evt::Ready ---
link (link-tcp) S->H: (0[0 / 0] requests pending)
07/10/13@16:26:59.023 RECEIVED: (12) bytes - System Status ('keep-alive' request)
@07/10/13@16:26:59.023 **** PBX::SystemStatus ****
link (link-tcp) S->H: System status request (id=677a [2]) from PBX (0[0 / 0] requests pending)
@16:27:13.398 DataFromSwitch 158 bytes
0000-000f: a1 81 9b 02 02 67 7c 02-01 15 30 81 91 55 04 01 |.....g|...0..U..|
0010-001f: 39 52 00 a0 49 a3 47 30-45 6b 0a 82 02 99 d5 83 |9R..I.G0Ek......|
0020-002f: 04 7d 02 01 03 63 09 84-07 35 38 33 30 37 33 32 |.}...c...5830732|
0030-003f: 61 0b 82 09 35 35 36 32-38 33 37 33 36 62 09 84 |a...556283736b..|
0040-004f: 07 35 38 33 30 37 33 32-64 02 88 00 6b 0a 82 02 |.5830732d...k...|
0050-005f: 99 d5 83 04 00 04 01 04-4e 01 02 0a 01 2a 7e 3e |........N....*~>|
0060-006f: a0 0f 17 0d 31 33 30 37-31 30 31 36 32 33 30 34 |....130710162304|
0070-007f: 5a a1 2b 30 12 06 06 2b-0c 89 36 84 09 04 08 48 |Z.+0...+..6....H|
0080-008f: 6e dd 51 d5 99 01 00 30-15 06 06 2b 0c 89 36 84 |n.Q....0...+..6.|
0090-009d: 0b a3 0b 82 09 35 35 36-32 38 33 37 33 36      |.....556283736  |
07/10/13@16:27:13.398 RECEIVED: 158 bytes
aPDU-rose invoke { -- SEQUENCE --
  invokeID 26492,
  operationValue 21,
  argument { -- SEQUENCE --
    crossRefIdentifier '01395200'H  -- ".9R." --,
    eventSpecificInfo callEvent deliveredEvent { -- SEQUENCE --
      connection { -- SEQUENCE --
        call '99d5'H  -- "™Õ" --,
        device dynamicID '7d020103'H  -- "}..." --
      },
      alertingDevice deviceIdentifier implicitPrivate '35383330373332'H  -- "5830732" --,
      callingDevice deviceIdentifier implicitPublic '353536323833373336'H  -- "556283736" --,
      calledDevice deviceIdentifier implicitPrivate '35383330373332'H  -- "5830732" --,
      lastRedirectionDevice notRequired NULL,
      originatingConnection { -- SEQUENCE --
        call '99d5'H  -- "™Õ" --,
        device dynamicID '00040104'H  -- "...." --
      },
      localConnectionInfo 2,
      cause 42
    },
    extensions { -- SEQUENCE --
      security { -- SEQUENCE --
        timeStamp '3133303731303136323330345a'H  -- "130710162304Z" --
      },
      privateData { -- SEQUENCE/SET OF --
        privateData { -- SEQUENCE --
          manufacturer {1 3 12 1206 521},
          '486edd51d5990100'H  -- "Hn QÕ™.." --
        },
        privateData { -- SEQUENCE --
          manufacturer {1 3 12 1206 523},
          explicitPublic national '353536323833373336'H  -- "556283736" --
        }
      }
    }
  }
}[/sup]




Regards.

[Kubig]

Attach logs before occurrence of EventAgentReady , from this log fragment is not possible to find out anything. It is important if before the Event was some request or not, if not, the command for change status was from PBX or directly from phone.

[alamitab]

I've attached the logs before.

In big lines the flow of events is like this:
EventRelaeased
EventOnHook
EventAgentReady
RequestAgentNotReady
EventAgentNotReady
EventAgentReady -----


[sup]@16:25:52.6490 [0] 7.6.003.05 distribute_event: message EventReleased
AttributeEventSequenceNumber 000000000007da37
AttributeTimeinuSecs 649000
AttributeTimeinSecs 1373466352 (16:25:52)
AttributeThisDN '844'
AttributeExtensions [252] 00 08 00 00..
'GCTI_SUB_THIS_DN' '1844'
'GCTI_BUSINESS_CALL' 1
'GCTI_LAST_REDIRECTION_DEVICE' '732'
'GCTI_NETWORK_TIMESLOT' 8
'GCTI_OLD_GLOB_CID' bin: EE 6D DD 51.. (len=8)
'GCTI_GLOB_CID' bin: D6 6D DD 51.. (len=8)
'GCTI_NAT_INDICATIONTYPE' 'Public:National'
'GCTI_NAT_INDICATION' '493182200'
AttributeNetworkCallID d66ddd51c0990100
AttributeCustomerID 'Resources'
AttributeANI '493182200'
AttributeDNIS '5830732'
AttributeUserData [465] 00 13 00 00..
'Service' 'Business'
'ANI' '0493182200'
'TelSAP' '0493182200'
'ACCOUNT' 'ANI:0493182200'
'Temp' '0000423840'
'Company' 'Multiple customers'
'TEL' '0493182200'
'MAINPARTNER' 'ANI:0493182200'
'COUNTRY' 'FR'
'DNIS' '5830732'
'CONNID' '0259022c2438ba3d'
'Message' 'FR_Attente'
'Myscript' '1879'
'ScriptName' 'FR_Attente'
'EAP' '1879'
'RPVQID' '001GGSLA5C8TF8VSIS5CM7TAES0005J5'
'RVQID' '001GGSLA5C8TF8VSIS5CM7TAES0005J5'
'RVQDBID' '2705'
'gplus-analytics-id' '12429c:13f79ec8a8a:-5608'
AttributeCallUUID '0V25V1C2MT2P18D38JG413O79400855N'
AttributeConnID 0259022c2438ba3d
AttributeCallID 39360
AttributeCallType 2
AttributeCallState 0
AttributeThirdPartyQueue '732'
AttributeOtherQueue '5830732'
AttributeThisQueue '732'
AttributeThisTrunk 362
AttributeThisDNRole 2
AttributeAgentID '1844'
AttributeOtherTrunk 262364
AttributeOtherDNRole 1
AttributeOtherDN '493182200'
@16:25:52.6490 [ISCC] Translate: '493182200' -> ''; result 1 ()
@16:25:52.6490 [ISCC] Party object is removed: p:0000000000000000,00000000 n::
16:25:52.649 Int 04544 Interaction message "EventReleased" generated
16:25:52.649 Trc 04542 EventReleased sent to [484] (0000000e StatServer80_Tz_EU-Wb 151.10.203.31:58077)
16:25:52.649 Trc 04542 EventReleased sent to [548] (00000009 GPlus_EU-West_b4 151.10.225.48:3458)
16:25:52.649 Trc 04542 EventReleased sent to [508] (00000006 FR_StatServer 151.10.96.47:2429)
16:25:52.649 Trc 04542 EventReleased sent to [472] (00000003 StatServerREP_80 151.10.203.31:58528)
16:25:52.649 Trc 04542 EventReleased sent to [452] (00000002 StatServerCCA_80 151.10.203.31:58527)
16:25:52.649 Trc 20021 Call 0259022c2438ba3d cleared with TReliabilityOk
  Party: <99c0:99d2:493182200@0126DE10> removed, state = (0-4)
  PartyDN: <99c0:99d2:844@01B6E5A8> removed, state = (0-4)
@16:25:52.6490 [0] 7.6.003.05 distribute_event: message EventReleased
AttributeEventSequenceNumber 000000000007da38
AttributeTimeinuSecs 649000
AttributeTimeinSecs 1373466352 (16:25:52)
AttributeCustomerID 'Resources'
AttributeANI '493182200'
AttributeDNIS '5830732'
AttributeUserData [465] 00 13 00 00..
'Service' 'Business'
'ANI' '0493182200'
'TelSAP' '0493182200'
'ACCOUNT' 'ANI:0493182200'
'Temp' '0000423840'
'Company' 'Multiple customers'
'TEL' '0493182200'
'MAINPARTNER' 'ANI:0493182200'
'COUNTRY' 'FR'
'DNIS' '5830732'
'CONNID' '0259022c2438ba3d'
'Message' 'FR_Attente'
'Myscript' '1879'
'ScriptName' 'FR_Attente'
'EAP' '1879'
'RPVQID' '001GGSLA5C8TF8VSIS5CM7TAES0005J5'
'RVQID' '001GGSLA5C8TF8VSIS5CM7TAES0005J5'
'RVQDBID' '2705'
'gplus-analytics-id' '12429c:13f79ec8a8a:-5608'
AttributeCallUUID '0V25V1C2MT2P18D38JG413O79400855N'
AttributeConnID 0259022c2438ba3d
AttributeCallID 39360
AttributeCallType 2
AttributeThisDN 'FR_Paris::'
@16:25:52.6490 [ISCC] Translate: '493182200' -> ''; result 1 ()
@16:25:52.6490 [ISCC] Party object is removed: p:0000000000000000,00000000 n::
@16:25:52.6490 [ISCC] Error: No call is associated with the event, skipped
@16:25:52.6490 [ISCC] Error: No call is associated with the event, skipped
@16:25:52.6490 [ISCC] Error: No call is associated with the event, skipped
@16:25:52.6490 [ISCC] Error: No call is associated with the event, skipped
16:25:52.649 Int 04544 Interaction message "EventReleased" generated
16:25:52.649 Trc 04542 EventReleased sent to [484] (0000000e StatServer80_Tz_EU-Wb 151.10.203.31:58077)
16:25:52.649 Trc 04542 EventReleased sent to [508] (00000006 FR_StatServer 151.10.96.47:2429)
16:25:52.649 Trc 04542 EventReleased sent to [472] (00000003 StatServerREP_80 151.10.203.31:58528)
16:25:52.649 Trc 04542 EventReleased sent to [452] (00000002 StatServerCCA_80 151.10.203.31:58527)
@16:25:52.6490 [ISCC] Call destroyed:
- c:0259022c2438ba3d,01b4e218 @ m:0000000000000000,00000000 p:0 i:000099c0 nw:d66ddd51c0990100 t:2
@16:25:52.6490 [ISCC] Call object is removed: c:0259022c2438ba3d,00000000
  TmCall::deleted(1:0): for <2:99c0:99cd:0@01B4E218> with rel (0)
  Call::~Call: (99c0:99c0:99cd:0)@01B4E218 deleted
@16:25:52.6490 {tscp.call {destructed} {uuid 0V25V1C2MT2P18D38JG413O79400855N} {connection-id 0259022c2438ba3d} {call-id 39360}}
@16:25:52.6490 [0] 7.6.003.05 distribute_event: message EventOnHook
AttributeEventSequenceNumber 000000000007da39
AttributeCustomerID 'Resources'
AttributeTimeinuSecs 649000
AttributeTimeinSecs 1373466352 (16:25:52)
AttributeAgentID '1844'
AttributeThisDN '844'
@16:25:52.6490 [ISCC] Translate: '' -> ''; result 1 ()
16:25:52.649 Int 04544 Interaction message "EventOnHook" generated
16:25:52.649 Trc 04542 EventOnHook sent to [484] (0000000e StatServer80_Tz_EU-Wb 151.10.203.31:58077)
16:25:52.649 Trc 04542 EventOnHook sent to [548] (00000009 GPlus_EU-West_b4 151.10.225.48:3458)
16:25:52.649 Trc 04542 EventOnHook sent to [508] (00000006 FR_StatServer 151.10.96.47:2429)
16:25:52.649 Trc 04542 EventOnHook sent to [472] (00000003 StatServerREP_80 151.10.203.31:58528)
16:25:52.649 Trc 04542 EventOnHook sent to [452] (00000002 StatServerCCA_80 151.10.203.31:58527)
@16:25:52.6490 [0] 7.6.003.05 distribute_event: message EventAgentReady
AttributeExtensions [53] 00 01 00 00..
'AgentSessionID' '0V25V1C2MT2P18D38JG413O794007JN1'
AttributeEventSequenceNumber 000000000007da3a
AttributeCustomerID 'Resources'
AttributeTimeinuSecs 649000
AttributeTimeinSecs 1373466352 (16:25:52)
AttributeAgentWorkMode 0 (Unknown)
AttributeThisQueue '5830200'
AttributeAgentID '1844'
AttributeThisDN '844'
@16:25:52.6490 [ISCC] Translate: '' -> ''; result 1 ()
16:25:52.649 Trc 04542 EventAgentReady sent to [484] (0000000e StatServer80_Tz_EU-Wb 151.10.203.31:58077)
16:25:52.649 Trc 04542 EventAgentReady sent to [548] (00000009 GPlus_EU-West_b4 151.10.225.48:3458)
16:25:52.649 Trc 04542 EventAgentReady sent to [508] (00000006 FR_StatServer 151.10.96.47:2429)
16:25:52.649 Trc 04542 EventAgentReady sent to [472] (00000003 StatServerREP_80 151.10.203.31:58528)
16:25:52.649 Trc 04542 EventAgentReady sent to [452] (00000002 StatServerCCA_80 151.10.203.31:58527)
--- Evt::ConnectionCleared ---
link (link-tcp) S->H: (0[0 / 0] requests pending)
16:25:52.805 Trc 04541 RequestAgentNotReady received from [548] (00000009 GPlus_EU-West_b4 151.10.225.48:3458)
message RequestAgentNotReady
AttributeAgentWorkMode 3 (AfterCallWork)
AttributeExtensions [2] 00 00..
AttributeReferenceID 33134
AttributeReason [21] 00 01 01 00..
'ReasonCode' 4
AttributeThisDN '844'
07/10/13@16:25:52.805 +++ RqHandler::RequestAgentNotReady +++
  got message from client <9>
  device <844> is replaced by <1844>
  [1844/-]: check device for 'RequestAgentNotReady'
  *** Transaction Info:
    Type/Oper. : 5 - 15 <Request : SetFeature>
    hostRef    : 1ffe
    SubjDev[0] : 1844 (Private)
    LocalDev[0]: 1844 (Unknown)
    CtiFeature : 1-4-0-0
    userInfo  : 9, 33134
@16:25:52.805 DataToSwitch 21 bytes
0000-000f: a1 13 02 02 1f fe 02 01-0f 30 0a 80 04 31 38 34 |.........0...184|
0010-0014: 34 a3 02 85 00        -                        |4....          |
invoke { -- SEQUENCE --
  invokeID 8190,
  operationValue 15,
  argument { -- SEQUENCE --
    device dialingNumber '31383434'H  -- "1844" --,
    feature aRequestedAgentState agentWrapUp NULL
  }
}
lnk> (link_write) link 1(link-tcp), 23 bytes
  H->S 23 bytes send, invoke id 8190 (x1ffe), 0[1] requests pending
--- RqHandler::RequestAgentNotReady ---
@16:25:52.821 DataFromSwitch 13 bytes
0000-000c: a2 0b 02 02 1f fe 30 05-02 01 0f 05 00          |......0......  |
07/10/13@16:25:52.821 RECEIVED: 13 bytes
aPDU-rose retResult { -- SEQUENCE --
  invokeID 8190,
  { -- SEQUENCE --
    operationValue 15,
    result noData NULL
  }
}
+++ Resp::SetFeature +++
  *** Transaction Info:
    Type/Oper. : 2 - 15 <Result : SetFeature>
    hostRef    : 1ffe
  [1844]: event received, for <RequestAgentNotReady:9:33134:72577:1>
  D[1844]::SetContext: ref <33134:72577>
  the feature 'agent state: working after call' for DN <1844>
  context is reset
--- Resp::SetFeature ---
link (link-tcp) S->H: (0[1 / 1] requests pending)
@16:25:52.930 DataFromSwitch 65 bytes
0000-000f: a1 3f 02 02 67 70 02 01-15 30 36 55 04 01 7a c0 |.?..gp...06U..z.|
0010-001f: 00 a2 1b a5 19 30 17 63-06 84 04 31 38 34 34 8a |.....0.c...1844.|
0020-002f: 04 31 38 34 34 80 07 35-38 33 30 32 30 30 7e 11 |.1844..5830200~.|
0030-003f: a0 0f 17 0d 31 33 30 37-31 30 31 36 32 31 34 34 |....130710162144|
0040-0040: 5a                    -                        |Z              |
07/10/13@16:25:52.930 RECEIVED: 65 bytes
aPDU-rose invoke { -- SEQUENCE --
  invokeID 26480,
  operationValue 21,
  argument { -- SEQUENCE --
    crossRefIdentifier '017ac000'H  -- ".zÀ." --,
    eventSpecificInfo agentStateEvent agentWrapUpEvent { -- SEQUENCE --
      agentDevice deviceIdentifier implicitPrivate '31383434'H  -- "1844" --,
      agentID '31383434'H  -- "1844" --,
      agentGroup dialingNumber '35383330323030'H  -- "5830200" --
    },
    extensions { -- SEQUENCE --
      security { -- SEQUENCE --
        timeStamp '3133303731303136323134345a'H  -- "130710162144Z" --
      }
    }
  }
}
cstaSwitchingEventDecode: WorkingAfterCall event in progress
+++ Evt::WorkingAfterCall +++
  *** Transaction Info:
    Type/Oper. : 1 - 208 <Event : WorkingAfterCall>
    crossRef  : 17ac000
    SubjDev[0] : 5830200 (Unknown)
    LocalDev[0]: 1844 (Private)
    LocalDev[1]: 1844 (Unknown)
    TimeStamp  : <130710162144Z>
  refDev <1844> (cref = '17AC000')
  D[1844]::SetContext: ref <33134:72577>
  TmRequest::RequestAgentNotReady::Add2Msg: context (9:33134:72577) is matched to [EventAgentNotReady], keep=0[/sup]

[Kubig]

Have you configured wrap-up? It seems like that

[alamitab]

From TServer options: 
[b]wrap-up-time=1000[/b]
...
legal-guard-acw=false
legal-guard-reason=0
legal-guard-time=0
....
[u]
I forgot to say that is not a repetitive event.[/u]

Could be something on switch side ?

Regards.

[Kubig]

Yes, of course. When the event is generated without previous Request from some component, it means that the event is generated directly from T-Server or from switch. So, check your settings of wrap-up on application and then on Agent or DN level (application level is lower level and the agent level overwrite it), if the configuration on Genesys will be ok. Check PBX configuration.

[alamitab]

Thanks. I'll ask to be verified on switch side.