Ticket Audit Log

[pk4]

I have been noticing some very bizarre behavior in the Ticket Audit log. I'm looking at a ticket right now that the audit log says is deleted (it isn't). I've seen a dozen tickets that have "closed" as the last action, but they're still open (probably same as http://www.wgmdev.com/jira/browse/CHD-547). I had a whole set of tickets today where the audit log shows actions by workers that are just not possible.

Pretty much, i'm seeing things that just don't make any sense at all.
Can someone speak to the status on this?

[dsugita]

Hey there,
Are you able to reproduce this issue in any way or does it seemingly happen at random? I myself haven't come across this issue, and I don't think Joe has seen it in any of his Q/A stiff (I'll ask him about it later), so if theres a definite way to reproduce this that you have seen, please let us know.

[pk4]

I don't know how to reproduce it yet, but i have more info

I noticed in the ticket_audit log table that there was a string of 124 false close entries (by my worker id) over a 6 second period. I checked the apache stats and here are the only hits that were anywhere close:

24.97.38.34 - - [22/Apr/2008:10:03:46 -0400] "POST /cerb4/ajax.php?c=tickets&a=viewCloseTickets&view_id=overview_all HTTP/1.1
" 200 15674
24.97.38.34 - - [22/Apr/2008:10:03:54 -0400] "GET /cerb4/ajax.php?c=tickets&a=refreshOverviewTotals HTTP/1.1" 200 15788

I haven't been able to discover any pattern of the tickets, but none of them were actually closed as far as I can tell.

Maybe that will help narrow it down?

[pk4]

Is anyone looking at this?

I would be happy to help figure out how to reproduce the problem - but i really need some additional information.
Can one of the developers tell me what user actions could potentially cause those apache log entries? It's a bit difficult to figure that out from our end.

It has become critical to nail this down, since one of our executives now doesn't trust the audit log (for good reason).

Thanks!

[Hildy]

Can one of the developers tell me what user actions could potentially cause those apache log entries? It's a bit difficult to figure that out from our end.

Hey, pk4,

We haven't seen this here, though we admittedly don't use the audit log that much (at least *I* don't). The audit log is an event driven plugin, meaning that it's not functionally dependant on anything in the gui. If you take a look in the plugins/cerberusweb.auditlog/plugin.xml file, you can see that it currently only monitors two events, "ticket.property.pre_change" and "ticket.delete".

The former fires when DAO_Ticket::update() is called, and the latter on DAO_Ticket::delete(). So anything that updates or deletes a ticket will fire an event that the auditlog should make a record of. From looking at your Apache logs entries, it looks like someone may have selected the entire list of tickets and clicked "close" or hit "c" on the keyboard (the hotkey for close).

[pk4]

From looking at your Apache logs entries, it looks like someone may have selected the entire list of tickets and clicked "close" or hit "c" on the keyboard (the hotkey for close).

Yeah, that was my first assumption - until it happened to ME, and i know i didn't do that. I don't even have any views that show anywhere near that number of tickets at one time. I noticed it within an hour of when it happened and i know i didn't do any action that could have done that.

Plus, there's the inconsistency that the tickets in question were never actually closed. There is an audit log entry saying they were closed, but they weren't closed.

There is definitely something broken here. My suspicion is that the event processing code (processing something like a single close) is triggering a group close in the audit log.

[pk4]

OK, I need to escalate this to a higher priority.
I have almost random audit logs coming up that are just not reality. It's causing havoc in my company. I would be happy to help debug this further if you would point me in the right direction.

The latest example: i have a ticket where I am the next worker. But the last audit log says that another worker took the ticket (set "next worker" to themselves).

[Hildy]

pk4, is this something where we could get a login to the desk and to your server to look at this firsthand?

[pk4]

I just checked the audit log table, that last action (the bogus audit log entry) was added to 2132 tickets, with continuous timestamps extending over 103 seconds.

(re: login, i have to see if we can open db access to outside, currently it's firewalled)

[Hildy]

Wow. that's insane. :-) I'll be looking at the code until I get your login info.

[pk4]

To reproduce this:
Go to any ticket list. Click "surrender" with no tickets checked. It will sit and churn for a while as it writes bogus ticket logs over pretty much all the tickets it can find.
(WARNING: don't do this unless you don't care about your ticket audit log or you just feel like some manual cleanup work)

The problem is here:
/cerb4/plugins/cerberusweb.auditlog/api/App.php approx line 40:

@$tickets = DAO_Ticket::getTickets($ticket_ids);

If $ticket_id's is an empty list, then getTickets returns pretty much everything (a whole block of tickets).
This code needs to check for an empty argument ($ticket_ids) and bail

Also, it should probably never get this far - the js code should bail before the ajax call - since the "surrender" (and similar operations) have nothing to do when there are no tickets checked.

[Hildy]

Great job on catching that, pk4!!

In hindsight, it's obvious why it's messed up, but without that critical bit of data... :-)

Interestingly, this bug has already been fixed and was checked in on Friday, as a totally unrelated problem. :-D We'd been auditing our mysql logs for slow queries, and noticed DAO_Ticket::getTickets(null) calls. We killed that because of the performance implications, and getting this one is just a big bonus. (That call will now return an empty array instead of a bunch of tickets.)

[pk4]

Nice work on cleaning that up :)