[Home]

Summary:ASTERISK-06052: [patch] API Manager report a unique id value, in place of time, in AgentLogoff event
Reporter:Fernando Romo (el_pop)Labels:
Date Opened:2006-01-11 13:53:31.000-0600Date Closed:2011-06-07 14:09:59
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Core/ManagerInterface
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) 6209.diff
( 1) api_manager_agent.debug
( 2) chan_agent-r7982-6209.diff
Description:In a Agent session, when force a logoff of the agent via CLI or API manager The value returned in the logintime is not the real time of the agent work, seems like epoch time (a kind of unique id)

****** ADDITIONAL INFORMATION ******

When the agent hangup the call started with AgentLogin in the dialplan, the API manager report this:

   Event: Agentlogoff
   Privilege: agent,all
   Agent: 1001
   Logintime: 20
   Uniqueid: 1137011175.19

If send in the CLI the command or via API manger:

pbx*CLI> agent logoff Agent/1001

The Event seems like this

  Event: Agentlogoff
  Privilege: agent,all
  Agent: 1001
  Logintime: 1137011282
  Uniqueid: 1137011257.20

Whe test wit a login and logout cycles of few seconds and the result is no coherent.

the asterisk is branch 1.2 update today and with a clean instalation:

Asterisk SVN-branch-1.2-r7976 built by root @ pbx on a i686 running Linux on 2006-01-11 18:28:16 UTC

Whe test with update systems with the same results.

Comments:By: Jason Parker (jparker) 2006-01-11 14:44:52.000-0600

Logintime is the total number of seconds the agent was logged in.  What are the expected results here?
By: Fernando Romo (el_pop) 2006-01-11 15:57:00.000-0600

a few seconds, the test log an agent for 10 and 20 seconds and logout by normal form and by agent logoff commnad

i you see, the ammount of 1137011282 seconds are 315,836.46 Hours of logged time! not the 10 or 20 seconds expected. This appear to me is a unique_id in place of the correct value.

In fact, if convert the epoch 1137011282 to date is equal Wed Jan 11 2006 14:28:02 GMT-0600 (CST), the time i make the tests.


By: Fernando Romo (el_pop) 2006-01-11 16:11:26.000-0600

and the wrong value are in queue_log too:

1137011282|1137011257.20|NONE|Agent/1001|AGENTLOGOFF|SIP/1716-0b5d|1137011282
1137011489|1137011484.21|NONE|Agent/1001|AGENTLOGIN|SIP/1716-1e65
1137011521|NONE|NONE|1001|AGENTCALLBACKLOGOFF||32|CommandLogoff
1137011521|1137011484.21|NONE|Agent/1001|AGENTLOGOFF|SIP/1716-1e65|1137011521
1137012216|1137012210.22|NONE|Agent/1001|AGENTLOGIN|SIP/1715-6d04

and must be

1137011200|1137011175.19|NONE|Agent/1001|AGENTLOGOFF|SIP/1716-e56c|20

the time are equal the unique id when force the logout of the agent.
By: Jason Parker (jparker) 2006-01-11 16:17:19.000-0600

Try this patch and let me know if it works.

Disclaimer on file.
By: Fernando Romo (el_pop) 2006-01-11 17:21:49.000-0600

The patch don't work, i recompile, remove /usr/lib/asterisk/modules and install and the error still in the same way


By: BJ Weschke (bweschke) 2006-01-12 20:14:40.000-0600

i cannot reproduce this with current svn /trunk. better question is how are you logging this agent in? everything I see with the logout relies on the correct time getting set when the agent logs in.
By: BJ Weschke (bweschke) 2006-01-13 10:46:52.000-0600

el_pop: pls provide some additional feedback to the questions posed. Otherwise, we'll close the bug and you can reopen when you're rdy to work this one with us again. Thanks.
By: Fernando Romo (el_pop) 2006-01-13 11:17:11.000-0600

bweschke:

i log the agent in the traditional way, make a extension in the dial plan:

exten => 9960,1,AgentLogin
exten => 9960,2,Hangup

and:
exten => 9970,1,AgentCallbackLogin(||${CALLERIDNUM}@local)
exten => 9970,2,Hangup

I reproduce the error with 3 clients, one using the trunk of SVN the other 2 with last checkout of asterisk 1.2

I forget: Yhe error happend in the two login forms and only when force the logout by CLI or API Manager


By: Fernando Romo (el_pop) 2006-01-13 11:37:18.000-0600

bweschke:

I read the code of chan_agent.c and see in the fuction agent_logoff() the time calc operation in this way:

  logintime = time(NULL) - p->loginstart;
  p->loginstart = 0;

I think, when we force the logout, the value of loginstart is equal to 0, in fact is the epoch time of the execution of the force logout command. Seems like the p->loginstart value are cleaned before the time diference calc. Thas way report the epoch of the current logout instruction.


By: BJ Weschke (bweschke) 2006-01-13 11:43:10.000-0600

el_pop. Yes. You're spot on. It's not the calculation itself. It's p->loginstart either not getting set correctly in the first place or getting cleared before getting calc'd. I looked around for this yesterday and tried to reproduce it and could not. If you can find the spot in the code, we'd be able to get this one fixed.
By: Jason Parker (jparker) 2006-01-13 12:08:32.000-0600

Are you sure you tested my patch properly?  If you look at the code, it only sets the value of p->loginstart to the current time, if loginstart is already 0.  It never gets initialized to 0, so it will only get set to the time AFTER it gets reset...or something.  My code simply initializes this value to 0.
By: Fernando Romo (el_pop) 2006-01-13 13:23:17.000-0600

umm... i found something very interesting in the API manager debug. Now with the last update of branch 1.2 i found the API manager send two events:

  Event: Agentcallbacklogoff
  Privilege: agent,all
  Agent: 1302
  Loginchan:
  Logintime: 24

  Event: Agentlogoff
  Privilege: agent,all
  Agent: 1302
  Logintime: 1137183311
  Uniqueid: 1137183277.25346

The agent as logged with the AgentLogin command in the extensions.conf, when whe use the CLI command "Agent logoff Agent/1302" the API sends two Events, one wrong but with the rigth logintime value, in the next time the value of p->loginstart is alredy 0, thas why show the epoch time.

The problem now is isolate why the logoff command send two events in place of one.

And the first Event don't have a UniqueID property in the event pack.


By: Fernando Romo (el_pop) 2006-01-13 13:32:53.000-0600

Ok, The scenarios are:

1) When login with "AgentLogin" and kick the agent with CLI "Agent logoff Agent/1302" the API Manager send two events: "Agentcallbacklogoff" first and "Agentlogoff" next.

2) When login with "AgentCallBackLogin" and kick the agent, the API Manager send a "Agentcallbacklogoff" without "uniqueid".

The time calculation are correct, the handle of notify events has a logical error.


By: Fernando Romo (el_pop) 2006-01-13 13:39:16.000-0600

And the Queue_log show:

1136843696|1136843688.1842|NONE|Agent/1301|AGENTLOGIN|SIP/9200-960a
1136843705|1136843688.1842|NONE|Agent/1301|AGENTLOGOFF|SIP/9200-960a|9
1136957611|NONE|NONE|NONE|QUEUESTART|
1136958198|NONE|NONE|NONE|QUEUESTART|
1136959261|NONE|NONE|NONE|QUEUESTART|
1137182940|1137182930.25274|NONE|Agent/1301|AGENTLOGIN|SIP/9200-8747
1137183004|1137182930.25274|NONE|Agent/1301|AGENTLOGOFF|SIP/9200-8747|64
1137183035|1137183025.25297|NONE|Agent/1302|AGENTLOGIN|SIP/9200-a9d4
1137183053|NONE|NONE|1302|AGENTCALLBACKLOGOFF||18|CommandLogoff
1137183053|1137183025.25297|NONE|Agent/1302|AGENTLOGOFF|SIP/9200-a9d4|1137183053
1137183261|1137183250.25341|NONE|Agent/1301|AGENTLOGIN|SIP/9200-274b
1137183271|1137183250.25341|NONE|Agent/1301|AGENTLOGOFF|SIP/9200-274b|10
1137183287|1137183277.25346|NONE|Agent/1302|AGENTLOGIN|SIP/9200-00b5
1137183311|NONE|NONE|1302|AGENTCALLBACKLOGOFF||24|CommandLogoff
1137183311|1137183277.25346|NONE|Agent/1302|AGENTLOGOFF|SIP/9200-00b5|1137183311
1137184048|1137184016.25464|NONE|Agent/1302|AGENTCALLBACKLOGIN|9200@local
1137184075|NONE|NONE|1302|AGENTCALLBACKLOGOFF|9200@local|27|CommandLogoff
1137184484|1137184471.25508|NONE|Agent/1302|AGENTCALLBACKLOGIN|9200@local
1137184533|1137184517.25513|NONE|Agent/1302|AGENTCALLBACKLOGOFF|9200@local|49|
By: BJ Weschke (bweschke) 2006-01-13 20:52:33.000-0600

el_pop: try 6209.diff. It's not going to resolve the issue with two events coming out from the action (because I'm not convinced that's wrong behavior) but it should make sure that Logintime is right for both responses.
By: Fernando Romo (el_pop) 2006-01-14 10:32:14.000-0600

bweschke:

I think is a bad behaivor. One AgentLogin command must end with a AgentLogoff event.

One AgentCallBackLogin must end with a AgentCallBackLogoff.

Is correct send an aditional AgentCallbackLogoff (without uniqueid) and another AgentLogoff with the Logintime Missed up?...

The answer is NO, is not coherent control in this way the events, is not logical.

the problem is with the "Agent logoff Agent/xxxx" or CLI and API-Manager, when use this, the chan_agent can't see the kind of Login used in first place. We need to checkc this. For mi is a Logic error. The "aditional" event clear the value of the p->loginstart field and then the second Event (and the right one) comes with a miss value.

What you think?
By: BJ Weschke (bweschke) 2006-01-14 10:41:03.000-0600

el_pop: You're not going to get a uniqueid when you logoff an agent via the CLI. You only get a uniqueid when a call itself spawned the agent action (login or logoff). With respect to the incorrect logintime, did you try the latest patch?
        I'm not ready to address two events being sent from this action because from what you're saying, it's been this way for quite some time and I'm not sure if we'd come into backward compatibility issues with external tools that expect both these logged events if we did undo this.
By: Fernando Romo (el_pop) 2006-01-14 11:39:26.000-0600

bweschke:

I try the patch later today.

I don't know of the backwards compatibity of other applications (you mention external applications), but we need to make the events report and handler with more logical and simple estructure.

if we generate one "X" action we need to close the Call with the "X-End" not with "X-END" and "Y-END" events. where X and Y are any action you want.

the problem could be solved externaly. but my insistence is clean and keep the logic of the Manager and results on the logs in the most logical way. if this is posible, we can make external applications (vg API Manager events handlers) more easy.

I make a set of external applications for Asterisk (i released GPL in few weeks), but each change in Asterisk versions (vg. 1.0. -> 1.0.9 -> 1.2 -> and so) we fund changes in the way API Manager sends the Events.

If you agree with me, this kind of lack of logic generate a lot of work and research for developers trying to make external applications. Using the ideas of Unix: "Keep simple as posible".
By: BJ Weschke (bweschke) 2006-01-16 12:58:48.000-0600

el_pop: I've asked some of the other Asterisk developers about proper behavior for sending events on logoff since I really had no opinion one way or the other, and they agree with your logic. Thus, we'll be fixing this so it only sends one event.
Did you try the patch to correct the issue with logintime?
By: BJ Weschke (bweschke) 2006-01-16 14:59:22.000-0600

6209.diff which goes against the latest version of /trunk (r8109) should consolidate the remainder of the event logging to manager and queue_log during an agent logoff situation and make certain that these events are not thrown twice during a logoff sequence and that logintime is reported correctly. Please test and let me know results.
By: Fernando Romo (el_pop) 2006-01-16 21:39:23.000-0600

I use the 6209.diff and well... the result is not the best, but now present this (debuging the API Manager) with a normal "AgentLogin" and the command "Agent logoff Agent/1001" in CLI:

  Event: Agentlogoff
  Privilege: agent,all
  Agent: 1001
  Logintime: 10
  Uniqueid: (null)    <= where is the uniqueid?, and the "Reason" commnet?

In a normal cicle, logon and hangup shows:

  Event: Agentlogin
  Privilege: agent,all
  Agent: 1001
  Channel: SIP/9200-f322
  Uniqueid: 1137470790.1

  Event: Agentlogoff
  Privilege: agent,all
  Agent: 1001
  Logintime: 8
  Uniqueid: 1137470790.1

When have the same UniqueID and we can match the events.

In the AgentCallBackLogin scenario we have in a normal cycle:

  Event: Agentcallbacklogin
  Privilege: agent,all
  Agent: 1001
  Loginchan: 9200
  Uniqueid: 1137471536.4

  Event: Agentcallbacklogoff
  Privilege: agent,all
  Agent: 1001
  Reason:
  Loginchan: 9200
  Logintime: 75
  Uniqueid: 1137471617.5

Here the uniqueid are not equal, but we have a separate methods of logout and i don't know if we can preserve the original uniqueid of the session.

And wen use the "AgentCallBackLogin" and force the logoff:

  Event: Agentcallbacklogin
  Privilege: agent,all
  Agent: 1001
  Loginchan: 9200
  Uniqueid: 1137471773.6

  Event: Agentcallbacklogoff
  Privilege: agent,all
  Agent: 1001
  Reason: CommandLogoff    <== this is a good idea.
  Loginchan: 9200
  Logintime: 21

If you see, we lost the uniqueid's in the force logoff mode. The logintime's are correct, but the uniqueid works in schemas of database control of the agent activity and has a useful info to match events.

In the first debugs i show when i start the report, the uniqueid appears but calculate time wrong.

Is posible to keep the uniqueid's equal in each cycle? a mean "AgentLogin" ==> "AgentLogoff", "AgentCallbackLogin" ==> "AgentCallBackLogoff" and the force of the logoff.

The think is make the Events more coherent, in some events appear the "Reason" field, in other not. The UniqueID could be present and perhaps not equal, but i think the agent channel keeps the id of echa login/logoff events. is posible to keep equal?

The idea of the Reason field is good, but if we crate a event called "AgentForceLogoff"? (just a simple idea):

  Event: Agentforcelogoff
  Privilege: agent,all
  Agent: 1001
  Loginchan: 9200
  Logintime: 21
  Uniqueid: 1137471773.6

the uniqueid value could be the same uniqueid who start the Agent Session or could be the current time(NULL). What you think?


By: Fernando Romo (el_pop) 2006-01-16 21:43:22.000-0600

The queue.log shows:

1137470741|1137470725.0|NONE|Agent/1001|AGENTLOGIN|SIP/9200-5a7c
1137470743|1137470725.0|NONE|Agent/1001|AGENTLOGOFF|SIP/9200-5a7c|2
1137470804|1137470790.1|NONE|Agent/1001|AGENTLOGIN|SIP/9200-f322
1137470812|1137470790.1|NONE|Agent/1001|AGENTLOGOFF|SIP/9200-f322|8
1137470844|1137470832.2|NONE|Agent/1001|AGENTLOGIN|SIP/9200-cee4
1137470854|(null)|NONE|Agent/1001|AGENTLOGOFF|(null)|10
1137471553|1137471536.4|NONE|Agent/1001|AGENTCALLBACKLOGIN|9200
1137471628|1137471617.5|NONE|Agent/1001|AGENTCALLBACKLOGOFF|9200|75|
1137471787|1137471773.6|NONE|Agent/1001|AGENTCALLBACKLOGIN|9200
1137471808|NONE|NONE|Agent/1001|AGENTCALLBACKLOGOFF|9200|21|CommandLogoff

If you see the forced logoff in the AgentLogin command don't send the "CommandLogoff" reason. not send the channel (ext) and the uniqueid is missing

The log could be:

1137470854|NONE|NONE|Agent/1001|AGENTLOGOFF|SIP/9200-1c|10|CommandLogoff

not

1137470854|(null)|NONE|Agent/1001|AGENTLOGOFF|(null)|10


By: Fernando Romo (el_pop) 2006-01-16 22:24:40.000-0600

I recompile Asterisk without the patch and make a round of test writing the API Manager events log in the attached file "api_manager_agent.debug" with the last Head of the svn trunk (Asterisk SVN-trunk-r8114).
By: Olle Johansson (oej) 2006-03-10 07:20:34.000-0600

Where are we with these problems? Any updates?
By: Fernando Romo (el_pop) 2006-03-10 18:45:13.000-0600

oej:

We make a workaround ignoring the Logintime, but is not the correct form.

is necesary to write in a coherent way the API manager messaging and results.

The problem persists in all versions of * (trunk and branch). Let me re-take the issue
By: Serge Vecher (serge-v) 2006-06-16 15:10:21

el_pop: any updates here?
By: Fernando Romo (el_pop) 2006-07-18 01:59:40

Verchers:

The problem persist in last versions, in 1.2.9.1 and head, i try to test in 1.2.10 and send my comments.

excuse my lack of activity but i am out for a long period and i take care of this reports again.
By: Serge Vecher (serge-v) 2006-09-01 14:23:06

el_pop: what's the status here?
By: Fernando Romo (el_pop) 2006-09-01 15:12:47

Whit last versions on 1.2.x still happen but with less frecuency. In head pass randomy and present a odd report a copuple times a day. i try to catch a event manager log for a day to send the error
By: jmls (jmls) 2006-11-01 10:16:58.000-0600

el_pop: were you able to catch any more errors ?
By: Fernando Romo (el_pop) 2006-11-01 14:26:41.000-0600

Still happend in lastest 1.2 SVN versions, i test 1.4 and see the same behaivor, let me test Trunk.
By: Fernando Romo (el_pop) 2007-02-23 21:33:31.000-0600

Same error in last version of 1.4 branch and Trunk:

Event: Agentcallbacklogoff
Privilege: agent,all
Timestamp: 1172287115.755658
Agent: 666
Reason: CommandLogoff
Loginchan:
Logintime: 21


------------------------

Event: Agentlogoff
Privilege: agent,all
Timestamp: 1172287115.757220
Agent: 666
Logintime: 1172287115
Uniqueid: hq-1172287090.56

and you see... two events on place of one? and the first event without unique-id


By: Tilghman Lesher (tilghman) 2007-08-13 12:37:38

This issue appears to have been fixed for 1.4 in revision 74998.  Given that 1.2 is receiving fixes only for security issues at this point, I'm closing this bug.  Please reopen this issue if it is still a problem for 1.4.