Audit logging

[Fishbowler]

To resolve #115

[guusdk]

I didn't cross-check, but this feels like we're adding an enum value for pretty much every endpoint? I'm not immediately seeing a better way, but that doesn't sit well with me.

[Fishbowler]

I'm not in love with it either, but it's that search for something better that's got me stumped. We could make it more freeform, but then it becomes a description in the progress towards structured logging, and there's no "event id" equivalent.

[guusdk]

Wouldn't this be pretty static, for by far most calls? Does this add enough value for it to be added?

[Fishbowler]

It's a private method that I added because it makes auditEvent more readable.

[Fishbowler]

Did I misunderstand this comment? It's getting the class and method of the caller of the audit event, and so feels useful.

A thought though - with well named classes and methods, do we actually need those enum values?
Instead of CLUSTER_GET_STATUS, we'd have ClusteringController::getClusterStatus. Would that be enough for an enterprise log analysis system, given that they're pretty stable? Current implementation has exactly 1 usage of each enum.

[guusdk]

I think this gets us what you're after, but I can't shake this feeling that the implementation depends on a lot of manual maintenance. My fear is that we end up forgetting to add this for new features, or mess up individual endpoint implementations by missing an argument, or somesuch.

You have previously expressed concern that capturing this information closer to the endpoint would make us miss context, but I don't think I see all that much more being logged than the endpoint being invoked, and the arguments being used. Is there no way to this with a generic filter, or something like that?

[Fishbowler]

Is there no way to this with a generic filter, or something like that?

Totally with you on this. The maintenance effort is far more than zero. I've sunk a bunch of time into AspectJ to grab info on method calls and parameters, but not only is it a bit odd, it'd require Openfire changes to support "weaving" at runtime.

Instead, I'd like to improve the logging in the AuthFilter - include the user, log the endpoint being hit, consider logging the parameters.

The only problem I've hit is that whilst I can wire the username to the service (through the request context), but not to the controller (have we named all of our classes backwards - shouldn't the controllers have the endpoints, and the services have the business logic?) so if we want to tie auditing of a result to tie to the request, we still end up passing 1 param from the endpoint to the controller method. The alternative is instantiating a controller for each user so that the object has the information once, but in some environments, I fear that could get unweildy.

[Fishbowler]

I've pushed some untested code to show what better logging in the AuthFilter might look like.

[guusdk]

I've got some questions (both on your last comment, as on the code changes). I realized that these questions might stem from a misalignment on what we're actually trying to achieve with this feature.

What data do we, and/or what data don't we want to have logged?

You're digging quite deep into the business logic (which adds to the complexity). When I am tasked to create logs than this, I typically go with the easiest (from a technical perspective) approach: log the HTTP request and response: either metadata directly from both (IP address, URL, response status code, etc) or even the full, raw data.

Granted, that is very much motivated by implementing something that is easy to build. I did not give much thought to the usability of that approach (for users that have to process the logged data) - but I assume that much data can be parsed from those logs. One thing that you'd miss this way is the state of whatever is being modified, prior to the modification taking place (but I don't think your implementation logs that either).

[Fishbowler]

Ideally, it'd be:

"User [user] fetched [something] and was told [X]"
..or..
"User [user] changed [something] from [X] to [Y]".

That's incredibly stateful, and logging aside, we regularly don't observe prior state before acting, since the activity is "set the state of [something] to [Y]" which we do, so long as Y is valid.

We get most of the way there through the stuff I've messed with in the AuthFilter (and well named endpoints) where we can infer:

"User [user] wanted to fetch [something]"
..or..
"User [user] wanted to set [something] to [Y]"

Perhaps this would be better as a separate filter that runs after Auth where we can gather the response too? With informative endpoints (e.g. when adding X to a list, return the resultant list) we'd be most of the way there.

We can't get the contextual stuff deeper into the business logic without wiring the Auth much deeper, creating noise on every method. It's gross. I think there are probably some good points in the business logic to be loud about important changes though.