Commit d8a6c806 authored by Matija Obreza's avatar Matija Obreza
Browse files

Fixed AuditLog interceptor and service

- Added new TransactionAuditLog class with equals() method to check the classPk, entityId and propertyName only
- TransactionAuditLogs are kept in a ThreadLocal HashSet that prevents multiple entries for the same classPk, entityId and propertyName
parent deff1f06
......@@ -17,6 +17,7 @@ package org.genesys.blocks.auditlog.component;
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;
......@@ -28,6 +29,7 @@ import java.util.HashSet;
import java.util.Map;
import java.util.Set;
import java.util.UUID;
import java.util.concurrent.atomic.AtomicLong;
import java.util.stream.Collectors;
import java.util.stream.Stream;
......@@ -40,11 +42,15 @@ import org.apache.commons.lang3.StringUtils;
import org.apache.commons.lang3.time.FastDateFormat;
import org.genesys.blocks.auditlog.annotations.Audited;
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.model.BasicModel;
import org.genesys.blocks.model.EntityId;
import org.hibernate.CallbackException;
import org.hibernate.EmptyInterceptor;
import org.hibernate.Transaction;
import org.hibernate.collection.spi.PersistentCollection;
import org.hibernate.type.Type;
import org.slf4j.Logger;
......@@ -109,10 +115,26 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
/** The time formatter. */
private Format timeFormatter;
/** Place to store audit logs before storing them to db */
private static final ThreadLocal<Set<TransactionAuditLog>> auditLogs = new ThreadLocal<Set<TransactionAuditLog>>() {
@Override
protected Set<TransactionAuditLog> initialValue() {
return new HashSet<>();
};
};
private static final ThreadLocal<AtomicLong> transactionStack = new ThreadLocal<AtomicLong>() {
@Override
protected AtomicLong initialValue() {
return new AtomicLong(0l);
};
};
/**
* Instantiates a new audit trail interceptor.
*/
public AuditTrailInterceptor() {
LOG.info("Enabling {}", getClass().getName());
// make synchronized local caches
ignoredClasses = Collections.synchronizedSet(new HashSet<>());
includedClasses = Collections.synchronizedSet(new HashSet<>());
......@@ -216,8 +238,6 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
return false;
}
final Date logDate = new Date();
// Identify changed values
for (int i = 0; i < previousState.length; i++) {
final String propertyName = propertyNames[i];
......@@ -237,7 +257,7 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
if (!StringUtils.equals(previousValue, currentValue)) {
// Notice cast to Long here!
recordChange(logDate, entity, (Long) id, propertyName, previousValue, currentValue, null);
recordChange(entity, (Long) id, propertyName, previousValue, currentValue, null);
}
} else if (isEntity(types[i].getReturnedClass())) {
final EntityId prevEntity = (EntityId) prev, currEntity = (EntityId) curr;
......@@ -246,10 +266,10 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
if (!StringUtils.equals(previousValue, currentValue)) {
// Notice cast to Long here!
recordChange(logDate, entity, (Long) id, propertyName, previousValue, currentValue, types[i].getReturnedClass());
recordChange(entity, (Long) id, propertyName, previousValue, currentValue, types[i].getReturnedClass());
}
} else {
LOG.warn("Entity.{} {} is not a primitive. Ignoring value={}", propertyName, prev == null ? null : prev.getClass(), prev);
LOG.trace("Entity.{} {} is not a primitive. Ignoring value={}", propertyName, prev == null ? null : prev.getClass(), prev);
// TODO Capture in audit log
}
}
......@@ -282,7 +302,7 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
temporalType = ta.value();
}
} catch (NoSuchFieldException | SecurityException e) {
LOG.warn("Could not access field {}#{}", entityClass, propertyName);
LOG.trace("Could not access field {}#{}", entityClass, propertyName);
}
switch (temporalType) {
......@@ -308,7 +328,7 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
if (EntityId.class.isAssignableFrom(clazz)) {
return true;
}
LOG.debug("{} is not an EntityId", clazz.getName());
LOG.trace("{} is not an EntityId", clazz.getName());
return false;
}
......@@ -326,11 +346,10 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
}
if (!isAudited(entityClass)) {
LOG.trace("{} is not audited", entityClass);
return;
}
final Date logDate = new Date();
for (int i = 0; i < states.length; i++) {
final String propertyName = propertyNames[i];
final Object state = states[i];
......@@ -340,16 +359,16 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
}
if (state != null) {
LOG.debug("Deleted prop={} state={} type={}", propertyName, state, types[i].getReturnedClass());
LOG.trace("Deleted prop={} state={} type={}", propertyName, state, types[i].getReturnedClass());
if (isPrimitiveType(types[i].getReturnedClass())) {
// Notice cast to Long here!
recordDelete(logDate, entity, (Long) id, propertyName, state == null ? null : state.toString(), null);
recordDelete(entity, (Long) id, propertyName, state == null ? null : state.toString(), 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(logDate, entity, (Long) id, propertyName, previousValue, types[i].getReturnedClass());
recordDelete(entity, (Long) id, propertyName, previousValue, types[i].getReturnedClass());
} else {
LOG.trace("Entity.{} {} is not a primitive. Ignoring value={}", propertyName, state == null ? null : state.getClass(), state);
// TODO Capture in audit log
......@@ -366,7 +385,7 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
*/
@Override
public void onCollectionRecreate(final Object collection, final Serializable key) throws CallbackException {
LOG.debug("Collection recreated: key={} coll={}", key, collection);
LOG.trace("Collection recreated: key={} coll={}", key, collection);
}
/*
......@@ -378,9 +397,10 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
public void onCollectionRemove(final Object collection, final Serializable key) throws CallbackException {
final PersistentCollection pc = (PersistentCollection) collection;
if (!isAudited(pc.getOwner().getClass())) {
LOG.trace("Class {} is not audited", pc.getOwner().getClass());
return;
}
LOG.debug("Collection remove: key={} coll={}", key, collection);
LOG.trace("Collection remove: key={} coll={}", key, collection);
final Class<? extends Object> ownerClass = pc.getOwner().getClass();
final String propertyName = pc.getRole().substring(pc.getRole().lastIndexOf('.') + 1);
......@@ -388,7 +408,6 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
LOG.trace("Property class: {}.{}={}", ownerClass.getName(), propertyName, propertyType);
Collection<Object> deleted = new HashSet<>();
final Date logDate = new Date();
if (pc.getValue() instanceof Collection<?>) {
deleted.addAll((Collection<?>) pc.getValue());
......@@ -397,13 +416,13 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
// If remaining is EntityId, convert to ID only
Class<?> referencedEntity = null;
if (EntityId.class.isAssignableFrom(propertyType)) {
LOG.debug("{} is EntityId, converting values.", propertyType.getName());
LOG.trace("{} is EntityId, converting values.", propertyType.getName());
referencedEntity = propertyType;
deleted = convertEntityId(deleted);
}
LOG.trace("prev=" + deleted.toString() + " curr=" + null);
recordDelete(logDate, pc.getOwner(), (Long) key, propertyName, deleted.toString(), referencedEntity);
recordDelete(pc.getOwner(), (Long) key, propertyName, deleted.toString(), referencedEntity);
}
/*
......@@ -415,18 +434,18 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
public void onCollectionUpdate(final Object collection, final Serializable key) throws CallbackException {
final PersistentCollection pc = (PersistentCollection) collection;
if (!isAudited(pc.getOwner().getClass())) {
LOG.trace("Class {} is not audited", pc.getOwner().getClass());
return;
}
LOG.debug("Collection update: key={} coll={}", key, collection);
LOG.trace("Collection update: key={} coll={}", key, collection);
final Class<? extends Object> ownerClass = pc.getOwner().getClass();
LOG.debug("ownerClass={} role={}", ownerClass.getName(), pc.getRole());
LOG.trace("ownerClass={} role={}", ownerClass.getName(), pc.getRole());
final String propertyName = pc.getRole().substring(pc.getRole().lastIndexOf('.') + 1);
final Class<?> propertyType = findPropertyType(ownerClass, propertyName);
LOG.trace("Property class: {}.{}={}", ownerClass.getName(), propertyName, propertyType);
Collection<Object> remaining = new HashSet<>();
final Date logDate = new Date();
if (pc.getValue() instanceof Collection<?>) {
remaining.addAll((Collection<?>) pc.getValue());
......@@ -449,14 +468,14 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
// If remaining is EntityId, convert to ID only
Class<?> referencedEntity = null;
if (EntityId.class.isAssignableFrom(propertyType)) {
LOG.debug("{} is EntityId, converting values.", propertyType.getName());
LOG.trace("{} is EntityId, converting values.", propertyType.getName());
referencedEntity = propertyType;
previous = convertEntityId(previous);
remaining = convertEntityId(remaining);
}
LOG.trace("prev=" + previous + " curr=" + remaining);
recordChange(logDate, pc.getOwner(), (Long) key, propertyName, previous.toString(), remaining.toString(), referencedEntity);
recordChange(pc.getOwner(), (Long) key, propertyName, previous.toString(), remaining.toString(), referencedEntity);
}
/**
......@@ -472,7 +491,7 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
// Field
final Field field = ReflectionUtils.findField(class1, propertyName);
if (field != null) {
LOG.debug("Found field: " + field + "\n\ttype=" + field.getType() + "\n\tgeneric=" + field.getGenericType() + "\n\tgenericTN=" + field.getGenericType().getTypeName());
LOG.trace("Found field: " + field + "\n\ttype=" + field.getType() + "\n\tgeneric=" + field.getGenericType() + "\n\tgenericTN=" + field.getGenericType().getTypeName());
final ResolvableType t = ResolvableType.forField(field, class1);
if (t.hasGenerics()) {
LOG.trace("\tResoved={} returning={}", t.toString(), t.resolveGeneric(0));
......@@ -487,7 +506,7 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
try {
final Method method = class1.getMethod("get" + StringUtils.capitalize(propertyName));
if (method != null) {
LOG.warn("Didn't find field, found the method: " + method.getReturnType().getTypeParameters()[0]);
LOG.trace("Didn't find field, found the method: " + method.getReturnType().getTypeParameters()[0]);
}
} catch (SecurityException | NoSuchMethodException e) {
e.printStackTrace();
......@@ -540,7 +559,7 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
return true;
}
if (LOG.isDebugEnabled()) {
LOG.debug("Class {} is not a primitive.", class1);
LOG.trace("Class {} is not a primitive.", class1);
}
return false;
}
......@@ -556,9 +575,16 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
* @param currentState the current state
* @param referencedEntity the referenced entity
*/
private void recordChange(final Date logDate, final Object entity, final Long id, final String propertyName, final String previousState, final String currentState,
private void recordChange(final Object entity, final Long id, final String propertyName, final String previousState, final String currentState,
final Class<?> referencedEntity) {
auditTrailService.recordChange(logDate, entity, id, propertyName, previousState, currentState, referencedEntity);
TransactionAuditLog change = auditTrailService.auditLogEntry(AuditAction.UPDATE, entity, id, propertyName, previousState, currentState, referencedEntity);
if (auditLogs.get().remove(change)) {
LOG.trace("Replacing exising changelog {}", change);
} else {
LOG.trace("Adding new changelog {}", change);
}
auditLogs.get().add(change);
}
/**
......@@ -571,8 +597,14 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
* @param state the state
* @param referencedEntity the referenced entity
*/
private void recordDelete(final Date logDate, final Object entity, final Long id, final String propertyName, final String state, final Class<?> referencedEntity) {
auditTrailService.recordDelete(logDate, entity, id, propertyName, state, referencedEntity);
private void recordDelete(final Object entity, final Long id, final String propertyName, final String state, final Class<?> referencedEntity) {
TransactionAuditLog delete = auditTrailService.auditLogEntry(AuditAction.DELETE, entity, id, propertyName, state, null, referencedEntity);
if (auditLogs.get().remove(delete)) {
LOG.trace("Replacing exising changelog {}", delete);
} else {
LOG.trace("Adding new changelog {}", delete);
}
auditLogs.get().add(delete);
}
/**
......@@ -593,15 +625,15 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
final NotAudited notAuditedAnnotation = entityClass.getAnnotation(NotAudited.class);
if (notAuditedAnnotation != null) {
LOG.debug("{} is exluded from auditing", entityClass);
LOG.trace("{} is exluded from auditing", entityClass);
// Register ignored class
ignoredClasses.add(entityClass);
return true;
return false;
}
final Audited auditedAnnotation = entityClass.getAnnotation(Audited.class);
if (auditedAnnotation != null) {
LOG.debug("{} is annotated for auditing", entityClass);
LOG.trace("{} is annotated for auditing", entityClass);
// Register included class
includedClasses.add(entityClass);
return true;
......@@ -609,7 +641,7 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
for (final Class<?> auditedClass : auditedClasses) {
if (auditedClass.isAssignableFrom(entityClass)) {
LOG.debug("{} is audited because it is an instance of {}", entityClass, auditedClass);
LOG.trace("{} is audited because it is an instance of {}", entityClass, auditedClass);
// Register included class
includedClasses.add(entityClass);
return true;
......@@ -621,4 +653,128 @@ public class AuditTrailInterceptor extends EmptyInterceptor implements Initializ
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) {
transactionStack.get().getAndIncrement();
LOG.trace("Starting transaction level={}", transactionStack.get().get());
// 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);
}
// Called before a transaction is committed (but not before rollback).
@Override
public void beforeTransactionCompletion(final Transaction tx) {
final long level = transactionStack.get().get();
LOG.trace("beforeTransactionCompletion transaction level={} auditlogs={}", level, auditLogs.get().size());
// LOG.trace("Before transaction completion status={} tx={}",
// tx.getLocalStatus(), tx);
if (level == 1 && auditLogs.get().size() > 0) {
LOG.trace("We have {} auditlogs", auditLogs.get().size());
auditLogs.get().stream().forEach(auditLog -> {
LOG.debug("Audit log to save: {}", auditLog);
});
this.auditTrailService.addAuditLogs(auditLogs.get());
auditLogs.get().clear();
}
super.beforeTransactionCompletion(tx);
}
// @SuppressWarnings({ "rawtypes", "unchecked" })
// @Override
// public void postFlush(final Iterator entities) {
// // LOG.trace("postFlush {}", entities);
// entities.forEachRemaining(entity -> {
// LOG.trace("postFlush {}", entity);
// });
//
// super.postFlush(entities);
// }
// Called after a transaction is committed or rolled back.
@Override
public void afterTransactionCompletion(Transaction tx) {
final long level = transactionStack.get().decrementAndGet();
LOG.trace("afterTransactionCompletion transaction level={} auditlogs={}", level, auditLogs.get().size());
if (tx.wasCommitted()) {
LOG.trace("Transaction was committed, have {} audit logs", auditLogs.get().size());
} else if (tx.wasRolledBack()) {
LOG.trace("Transaction was rolled back, have {} audit logs", auditLogs.get().size());
}
if (level == 0) {
// clear pending logs if back to level 0
auditLogs.get().clear();
}
super.afterTransactionCompletion(tx);
}
@Override
public Boolean isTransient(final Object entity) {
if (entity instanceof BasicModel) {
return !((BasicModel) entity).isPersisted();
}
// TODO Use Spring field access methods?
try {
return tryMethod(entity, "getVersion");
} catch (final NoSuchMethodException e) {
try {
return tryMethod(entity, "getId");
} catch (NoSuchMethodException | IllegalAccessException | InvocationTargetException e1) {
throw new RuntimeException(e.getMessage() + " on " + entity.getClass() + " e=" + entity, e);
}
} catch (final Throwable e) {
throw new RuntimeException(e.getMessage() + " on " + entity.getClass() + " e=" + entity, e);
}
}
public Boolean tryMethod(final Object entity, final String methodName) throws NoSuchMethodException, IllegalAccessException, InvocationTargetException {
final Method getter = entity.getClass().getMethod(methodName);
if (getter != null) {
final Object result = getter.invoke(entity);
if (result == null) {
LOG.trace(entity + " is transient, has " + methodName + " == null");
return true;
} else if (result instanceof Number) {
final Number r = (Number) result;
if (r.longValue() < 0) {
LOG.trace(entity + " is transient, has " + methodName + " = " + result + " < 0");
return true;
} else {
// LOG.trace(entity + " is not transient, has " + methodName + " = " + result +
// " >= 0");
return false;
}
} else {
// LOG.trace(entity + " is not transient, has " + methodName + " = " + result);
return false;
}
} else {
LOG.trace("No version method.");
throw new RuntimeException("No version method");
}
}
}
/*
* Copyright 2017 Global Crop Diversity Trust
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
package org.genesys.blocks.auditlog.model;
import org.genesys.blocks.model.ClassPK;
/**
* Temporary audit log.
*/
public class TransactionAuditLog {
/** Class name of the referenced entity. */
private ClassPK classPk;
/** ID of the referenced entity. */
private long entityId;
/** The name of the property modified. */
private String propertyName;
/** The type of entity referenced in the changed property. */
private ClassPK referencedEntity;
/** String representation of the previous state. */
private String previousState;
/** String representation of the updated state. */
private String newState;
/** The action. */
private AuditAction action;
/**
* Gets the class pk.
*
* @return the class pk
*/
public ClassPK getClassPk() {
return classPk;
}
/**
* Sets the class pk.
*
* @param classPk the new class pk
*/
public void setClassPk(final ClassPK classPk) {
this.classPk = classPk;
}
/**
* Gets the entity id.
*
* @return the entity id
*/
public long getEntityId() {
return entityId;
}
/**
* Sets the entity id.
*
* @param entityId the new entity id
*/
public void setEntityId(final long entityId) {
this.entityId = entityId;
}
/**
* Sets the property name.
*
* @param propertyName the new property name
*/
public void setPropertyName(final String propertyName) {
this.propertyName = propertyName;
}
/**
* Gets the property name.
*
* @return the property name
*/
public String getPropertyName() {
return propertyName;
}
/**
* Sets the referenced entity.
*
* @param referencedEntity the new referenced entity
*/
public void setReferencedEntity(final ClassPK referencedEntity) {
this.referencedEntity = referencedEntity;
}
/**
* Gets the referenced entity.
*
* @return the referenced entity
*/
public ClassPK getReferencedEntity() {
return referencedEntity;
}
/**
* Sets the previous state.
*
* @param previousState the new previous state
*/
public void setPreviousState(final String previousState) {
this.previousState = previousState;
}
/**
* Gets the previous state.
*
* @return the previous state
*/
public String getPreviousState() {
return previousState;
}
/**
* Sets the new state.
*