Commit 807de2c2 authored by Matija Obreza's avatar Matija Obreza
Browse files

Audits: New approach to recording changes

parent b973e590
......@@ -19,36 +19,29 @@ import java.io.Serializable;
import java.lang.reflect.Field;
import java.lang.reflect.InvocationTargetException;
import java.lang.reflect.Method;
import java.text.Format;
import java.util.ArrayList;
import java.util.Calendar;
import java.util.Collection;
import java.util.Collections;
import java.util.Date;
import java.util.HashMap;
import java.util.HashSet;
import java.util.List;
import java.util.Map;
import java.util.Set;
import java.util.Stack;
import java.util.UUID;
import java.util.stream.Collectors;
import java.util.stream.Stream;
import javax.persistence.EntityManager;
import javax.persistence.PersistenceContext;
import javax.persistence.Temporal;
import javax.persistence.TemporalType;
import org.apache.commons.lang3.StringUtils;
import org.apache.commons.lang3.time.FastDateFormat;
import org.apache.commons.lang3.tuple.Pair;
import org.genesys.blocks.auditlog.annotations.Audited;
import org.genesys.blocks.auditlog.annotations.HideAuditValue;
import org.genesys.blocks.auditlog.annotations.NotAudited;
import org.genesys.blocks.auditlog.model.AuditAction;
import org.genesys.blocks.auditlog.model.AuditLog;
import org.genesys.blocks.auditlog.model.TransactionAuditLog;
import org.genesys.blocks.auditlog.service.AuditTrailService;
import org.genesys.blocks.auditlog.service.AuditTrailService.ChangeKey;
import org.genesys.blocks.auditlog.service.AuditTrailService.PropertyChange;
import org.genesys.blocks.auditlog.service.impl.AuditTrailServiceImpl;
import org.genesys.blocks.model.BasicModel;
import org.genesys.blocks.model.EntityId;
import org.hibernate.CallbackException;
......@@ -89,9 +82,6 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
/** The ignored properties of audited entities. */
private final Map<Class<?>, Set<String>> ignoredClassFields;
/** The secured properties of audited entities. */
private final Map<Class<?>, Set<String>> securedClassFields;
/** The audited classes. */
private Set<Class<?>> auditedClasses = new HashSet<>();
......@@ -107,30 +97,11 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
@PersistenceContext
private EntityManager entityManager;
/** The date format. */
private final String dateFormat = "dd-MMM-yyyy";
/** The time format. */
private final String timeFormat = "HH:mm:ss";
/** The date time format. */
private final String dateTimeFormat = "dd-MMM-yyyy HH:mm:ss";
/** The date formatter. */
private Format dateFormatter;
/** The date time formatter. */
private Format dateTimeFormatter;
/** The time formatter. */
private Format timeFormatter;
/** Place to store audit logs before storing them to db */
private static final ThreadLocal<Stack<Set<TransactionAuditLog>>> auditLogStack = new ThreadLocal<Stack<Set<TransactionAuditLog>>>() {
private static final ThreadLocal<Stack<Map<AuditTrailService.ChangeKey, Map<String, PropertyChange<?>>>>> auditLogStack = new ThreadLocal<Stack<Map<AuditTrailService.ChangeKey, Map<String, PropertyChange<?>>>>>() {
@Override
protected Stack<Set<TransactionAuditLog>> initialValue() {
return new Stack<Set<TransactionAuditLog>>();
protected Stack<Map<AuditTrailService.ChangeKey, Map<String, PropertyChange<?>>>> initialValue() {
return new Stack<Map<AuditTrailService.ChangeKey, Map<String, PropertyChange<?>>>>();
};
};
......@@ -143,7 +114,6 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
ignoredClasses = Collections.synchronizedSet(new HashSet<>());
includedClasses = Collections.synchronizedSet(new HashSet<>());
ignoredClassFields = Collections.synchronizedMap(new HashMap<>());
securedClassFields = Collections.synchronizedMap(new HashMap<>());
}
/*
......@@ -158,10 +128,6 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
// Make them unmodifiable
ignoredProperties = Collections.unmodifiableSet(ignoredProperties);
auditedClasses = Collections.unmodifiableSet(auditedClasses);
dateFormatter = FastDateFormat.getInstance(dateFormat);
dateTimeFormatter = FastDateFormat.getInstance(dateTimeFormat);
timeFormatter = FastDateFormat.getInstance(timeFormat);
}
/**
......@@ -246,6 +212,8 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
final Set<String> entityIgnoredFields = ignoredClassFields.get(entityClass);
var changes = new HashMap<String, PropertyChange<?>>();
// Identify changed values
for (int i = 0; i < previousState.length; i++) {
final String propertyName = propertyNames[i];
......@@ -258,79 +226,25 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
}
if (((prev != null) && !prev.equals(curr)) || ((prev == null) && (curr != null))) {
LOG.trace("prop={} prev={} curr={} type={}", propertyName, prev, curr, types[i].getReturnedClass());
if (isPrimitiveType(types[i].getReturnedClass())) {
final String currentValue = formatValue(curr, types[i], entityClass, propertyName);
final String previousValue = formatValue(prev, types[i], entityClass, propertyName);
// Notice cast to Long here!
recordChange(entity, (Long) id, propertyName, previousValue, currentValue, null, prev, curr);
} else if (isEntity(types[i].getReturnedClass())) {
final EntityId prevEntity = (EntityId) prev, currEntity = (EntityId) curr;
final String previousValue = prevEntity == null ? null : prevEntity.getId().toString();
final String currentValue = currEntity == null ? null : currEntity.getId().toString();
if (!StringUtils.equals(previousValue, currentValue)) {
// Notice cast to Long here!
recordChange(entity, (Long) id, propertyName, previousValue, currentValue, types[i].getReturnedClass(), prev, curr);
}
var propertyType = types[i].getReturnedClass();
LOG.trace("prop={} prev={} curr={} type={}", propertyName, prev, curr, propertyType);
if (AuditTrailServiceImpl.isPrimitiveType(propertyType)) {
changes.put(propertyName, PropertyChange.of(propertyType, prev, curr));
} else if (isEntity(propertyType)) {
changes.put(propertyName, PropertyChange.of(propertyType, prev, curr));
} else {
LOG.trace("Entity.{} {} is not a primitive. Ignoring value={}", propertyName, prev == null ? null : prev.getClass(), prev);
// TODO Capture in audit log
}
}
}
recordChanges(entity, (Long) id, changes);
return false;
}
/**
* Format value.
*
* @param someValue the some value
* @param type the type
* @param entityClass the entity class
* @param propertyName the property name
* @return the string
*/
private String formatValue(final Object someValue, final Type type, final Class<?> entityClass, final String propertyName) {
if (someValue == null) {
return null;
}
// Check if field should be masked
final Set<String> securedFields = securedClassFields.get(entityClass);
if (securedFields != null && securedFields.contains(propertyName)) {
return AuditLog.FIELD_VALUE_NOT_AUDITED;
}
final Class<?> returnedClass = type.getReturnedClass();
if (Date.class.equals(returnedClass) || Calendar.class.equals(returnedClass)) {
TemporalType temporalType = TemporalType.TIMESTAMP;
try {
final Field field = entityClass.getDeclaredField(propertyName);
if ((field != null) && field.isAnnotationPresent(Temporal.class)) {
final Temporal ta = field.getAnnotation(Temporal.class);
temporalType = ta.value();
}
} catch (NoSuchFieldException | SecurityException e) {
LOG.trace("Could not access field {}#{}", entityClass, propertyName);
}
switch (temporalType) {
case TIMESTAMP:
return dateTimeFormatter.format(someValue);
case DATE:
return dateFormatter.format(someValue);
case TIME:
return timeFormatter.format(someValue);
}
}
return someValue.toString();
}
/**
* Checks if is entity.
*
......@@ -365,6 +279,8 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
final Set<String> entityIgnoredFields = ignoredClassFields.get(entityClass);
var changes = new HashMap<String, PropertyChange<?>>();
for (int i = 0; i < states.length; i++) {
final String propertyName = propertyNames[i];
final Object state = states[i];
......@@ -374,23 +290,21 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
}
if (state != null) {
LOG.trace("Deleted prop={} state={} type={}", propertyName, state, types[i].getReturnedClass());
if (isPrimitiveType(types[i].getReturnedClass())) {
// Notice cast to Long here!
recordDelete(entity, (Long) id, propertyName, state.toString(), null, null);
} else if (isEntity(types[i].getReturnedClass())) {
final EntityId prevEntity = (EntityId) state;
final String previousValue = prevEntity == null ? null : prevEntity.getId().toString();
// Notice cast to Long here!
recordDelete(entity, (Long) id, propertyName, previousValue, types[i].getReturnedClass(), state);
var propertyType = types[i].getReturnedClass();
LOG.trace("Deleted prop={} state={} type={}", propertyName, state, propertyType);
if (AuditTrailServiceImpl.isPrimitiveType(propertyType)) {
changes.put(propertyName, PropertyChange.of(propertyType, state, null));
} else if (isEntity(propertyType)) {
changes.put(propertyName, PropertyChange.of(propertyType, state, null));
} else {
LOG.trace("Entity.{} {} is not a primitive. Ignoring value={}", propertyName, state == null ? null : state.getClass(), state);
// TODO Capture in audit log
// PersistentBag
}
}
}
recordDelete(entity, (Long) id, changes);
}
/*
......@@ -440,16 +354,10 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
Serializable snap = pc.getStoredSnapshot();
LOG.trace("Collection remove: key={} coll={} snap={}", key, collection, snap);
// If remaining is EntityId, convert to ID only
Class<?> referencedEntity = null;
if (EntityId.class.isAssignableFrom(propertyType)) {
LOG.trace("{} is EntityId, converting values.", propertyType.getName());
referencedEntity = propertyType;
deleted = convertEntityId(deleted);
}
LOG.trace("prev={} curr=null", deleted);
recordDelete(pc.getOwner(), (Long) key, propertyName, deleted.toString(), referencedEntity, deleted);
var changes = new HashMap<String, PropertyChange<?>>();
changes.put(propertyName, PropertyChange.of(propertyType, deleted, null));
recordDelete(pc.getOwner(), (Long) key, changes);
}
/*
......@@ -498,38 +406,10 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
LOG.trace("Can't handle snap={} val={}", snap.getClass(), snap);
}
// If remaining is EntityId, convert to ID only
Class<?> referencedEntity = null;
if (EntityId.class.isAssignableFrom(propertyType)) {
LOG.trace("{} is EntityId, converting values.", propertyType.getName());
referencedEntity = propertyType;
previous = convertEntityId(previous);
remaining = convertEntityId(remaining);
}
LOG.trace("prev={} curr={}", previous, remaining);
recordChange(pc.getOwner(), (Long) key, propertyName, collectionToStringSorted(previous), collectionToStringSorted(remaining), referencedEntity, previous, remaining);
}
/**
* Produce a string representation of the collection. Set elements are sorted,
* other collection types return `#toString`.
*
* @param collection the collection
* @return the string
*/
private String collectionToStringSorted(Collection<?> collection) {
if (collection == null) {
return null;
}
if (collection instanceof Set<?>) {
LOG.trace("Converting to sorted list {} -> {}", collection, collection.stream().sorted().map(Object::toString).collect(Collectors.joining(", ", "[", "]")));
return collection.stream().sorted().map(Object::toString).collect(Collectors.joining(", ", "[", "]"));
} else {
LOG.trace("Not sorting {}: {}", collection.getClass(), collection);
}
return collection.toString();
var changes = new HashMap<String, PropertyChange<?>>();
changes.put(propertyName, PropertyChange.of(propertyType, previous, remaining));
recordChanges(pc.getOwner(), (Long) key, changes);
}
/**
......@@ -568,208 +448,53 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
return null;
}
/**
* Convert entity id.
*
* @param previous the previous
* @return the collection
*/
private Collection<Object> convertEntityId(final Collection<?> previous) {
final List<Object> converted = new ArrayList<>();
for (final Object p : previous) {
if (p instanceof EntityId) {
converted.add(((EntityId) p).getId());
} else {
converted.add(p);
}
}
converted.sort((a, b) -> {
if (a instanceof Long && b instanceof Long) {
return Long.compare((Long) a, (Long) b);
} else {
return Integer.compare(a.hashCode(), b.hashCode());
}
});
return converted;
}
/**
* Checks if class is a "primitive".
*
* @param class1 the property class
* @return true, if is primitive
*/
boolean isPrimitiveType(final Class<?> class1) {
if (class1.isPrimitive()) {
return true;
} else if (class1.isEnum()) {
return true;
} else if (class1.isArray()) {
return false;
} else if (Number.class.isAssignableFrom(class1)) {
return true;
} else if (String.class.equals(class1)) {
return true;
} else if (Character.class.equals(class1)) {
return true;
} else if (Boolean.class.equals(class1)) {
return true;
} else if (Date.class.equals(class1)) {
return true;
} else if (UUID.class.equals(class1)) {
return true;
}
if (LOG.isDebugEnabled()) {
LOG.trace("Class {} is not a primitive.", class1);
}
return false;
}
/**
* Record change.
*
* @param entity the entity
* @param id the id
* @param propertyName the property name
* @param previousState the previous state
* @param currentState the current state
* @param referencedEntity the referenced entity
* @param curr previousEntit
* @param prev currentEntity
*/
private void recordChange(final Object entity, final Long id, final String propertyName, final String previousState, final String currentState,
final Class<?> referencedEntity, Object prev, Object curr) {
if (StringUtils.equals(previousState, currentState) && !StringUtils.equals(currentState, AuditLog.FIELD_VALUE_NOT_AUDITED)) {
LOG.trace("No state change {}.{} {}=={}", entity.getClass(), id, previousState, currentState);
return;
}
TransactionAuditLog change = auditTrailService.auditLogEntry(AuditAction.UPDATE, entity, id, propertyName, previousState, currentState, referencedEntity, prev, curr);
if (auditLogStack.get().peek().remove(change)) {
LOG.trace("Replacing existing changelog {}", change);
} else {
LOG.trace("Adding new changelog {}", change);
}
auditLogStack.get().peek().add(change);
}
/**
* Record delete.
*
* @param entity the entity
* @param id the id
* @param propertyName the property name
* @param state the state
* @param referencedEntity the referenced entity
*/
private void recordDelete(final Object entity, final Long id, final String propertyName, final String state, final Class<?> referencedEntity, final Object prev) {
String stateToLog = state;
// Check fields masked with @HideAuditValue
if (stateToLog != null) {
final Set<String> securedFields = securedClassFields.get(entity.getClass());
stateToLog = securedFields != null && securedFields.contains(propertyName) ? AuditLog.FIELD_VALUE_NOT_AUDITED : state;
}
TransactionAuditLog delete = auditTrailService.auditLogEntry(AuditAction.DELETE, entity, id, propertyName, stateToLog, null, referencedEntity, prev, null);
if (auditLogStack.get().peek().remove(delete)) {
LOG.trace("Replacing exising changelog {}", delete);
private void recordChanges(Object entity, Long id, HashMap<String, PropertyChange<?>> changes) {
LOG.debug("Recording changes {}#{}", entity.getClass(), id, changes);
AuditTrailService.ChangeKey changeKey = AuditTrailService.ChangeKey.of(AuditAction.UPDATE, entity.getClass(), id);
var stack = auditLogStack.get().peek();
var stackUpdates = stack.get(changeKey);
if (stackUpdates == null) {
LOG.trace("Adding new changes:\tnew={}", changes);
stack.put(changeKey, changes);
} else {
LOG.trace("Adding new changelog {}", delete);
}
auditLogStack.get().peek().add(delete);
}
/**
* Determines if the entity class should be audited.
*
* @param entityClass entity class
* @return <code>true</code> when changes should be audited
*/
boolean isAudited(final Class<?> entityClass) {
// Cache lookup
if (includedClasses.contains(entityClass)) {
return true;
}
// Cache lookup
if (ignoredClasses.contains(entityClass)) {
return false;
}
final NotAudited notAuditedAnnotation = entityClass.getAnnotation(NotAudited.class);
if (notAuditedAnnotation != null) {
LOG.trace("{} is excluded from auditing", entityClass);
// Register ignored class
ignoredClasses.add(entityClass);
return false;
}
final Audited auditedAnnotation = entityClass.getAnnotation(Audited.class);
if (auditedAnnotation != null) {
LOG.trace("{} is annotated for auditing", entityClass);
// Register included class
includedClasses.add(entityClass);
ReflectionUtils.doWithFields(entityClass, field -> {
if (field.getAnnotation(NotAudited.class) != null) {
Set<String> ignoredEntityFields = ignoredClassFields.getOrDefault(entityClass, new HashSet<>());
LOG.trace("{} property of {} class is excluded from auditing", field.getName(), entityClass);
ignoredEntityFields.add(field.getName());
ignoredClassFields.put(entityClass, ignoredEntityFields);
}
if (field.getAnnotation(HideAuditValue.class) != null) {
Set<String> securedFields = securedClassFields.getOrDefault(entityClass, new HashSet<>());
LOG.trace("Previous and a new value of {} property of {} class is excluded from persisting", field.getName(), entityClass);
securedFields.add(field.getName());
securedClassFields.put(entityClass, securedFields);
LOG.trace("Updating existing changes:\n\twas={}\n\tadd={}", stackUpdates, changes);
// Merge new changes with existing changes
changes.entrySet().forEach((entry) -> {
var existingChange = stackUpdates.get(entry.getKey());
if (existingChange == null) {
// A new change
stackUpdates.put(entry.getKey(), entry.getValue());
} else {
// Update the existing change.value with new change.value
existingChange.change = Pair.of(existingChange.change.getKey(), entry.getValue().change.getValue());
}
});
return true;
}
}
for (final Class<?> auditedClass : auditedClasses) {
if (auditedClass.isAssignableFrom(entityClass)) {
LOG.trace("{} is audited because it is an instance of {}", entityClass, auditedClass);
// Register included class
includedClasses.add(entityClass);
return true;
}
private void recordDelete(Object entity, Long id, HashMap<String, PropertyChange<?>> changes) {
LOG.debug("Recording delete {}#{}", entity.getClass(), id, changes);
AuditTrailService.ChangeKey changeKey = AuditTrailService.ChangeKey.of(AuditAction.DELETE, entity.getClass(), id);
var stack = auditLogStack.get().peek();
var stackUpdates = stack.get(changeKey);
if (stackUpdates == null) {
LOG.trace("Adding new changes {}", changes);
stack.put(changeKey, changes);
} else {
LOG.trace("Updating existing changes {}", changes);
stackUpdates.putAll(changes);
}
LOG.trace("{} is not audited", entityClass);
// Register ignored entity class
ignoredClasses.add(entityClass);
return false;
}
// @Override
// public boolean onSave(Object entity, Serializable id, Object[] state,
// String[] propertyNames, Type[] types) {
// LOG.trace("onSave entity={} id={} props={}", entity, id,
// Arrays.toString(propertyNames));
// return super.onSave(entity, id, state, propertyNames, types);
// }
@Override
public void afterTransactionBegin(final Transaction tx) {
// Push new auditLogs to the stack
auditLogStack.get().push(new HashSet<>());
auditLogStack.get().push(new HashMap<>());
LOG.trace("Starting transaction level={}", auditLogStack.get().size());
// tx.registerSynchronization(new Synchronization() {
//
// @Override
// public void beforeCompletion() {
// LOG.trace("callback beforeCompletion");
// }
//
// @Override
// public void afterCompletion(int status) {
// LOG.trace("callback afterCompletion status={}", status);
// }
// });
super.afterTransactionBegin(tx);
}
......@@ -778,18 +503,15 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
public void beforeTransactionCompletion(final Transaction tx) {
final long level = auditLogStack.get().size();
Set<TransactionAuditLog> currentAuditLogs = auditLogStack.get().pop(); // pop
Map<ChangeKey, Map<String, PropertyChange<?>>> currentAuditLogs = auditLogStack.get().pop(); // pop
LOG.trace("beforeTransactionCompletion transaction level={} auditlogs={}", level, currentAuditLogs.size());
// LOG.trace("Before transaction completion status={} tx={}",
// tx.getLocalStatus(), tx);
if (currentAuditLogs.size() > 0) {
LOG.trace("We have {} auditlogs", currentAuditLogs.size());
currentAuditLogs.stream().forEach(auditLog -> {
LOG.debug("Audit log to save: {}", auditLog);
});
// currentAuditLogs.stream().forEach(auditLog -> {
// LOG.debug("Audit log to save: {}", auditLog);
// });
if (tx.getStatus().equals(TransactionStatus.ROLLED_BACK)) {
LOG.warn("Transaction was rolled back. Audit logs likely won't be persisted");