Hibernate - DB audit Logging

Hibernate -DB audit logging (How about this....................)
(Leave me a note if you have any comments improvements, corrections)

I looked around the web to see if there is any logging that can be done on the entities that are persisted using hibernate.

I found one interesting post on the hibernate site, one thing was missing:
The logging done in this article is based on entities names (the process will parse out the method name and the class name, and it will use that as the names of the columns and tables).

http://www.hibernate.org/318.html

I needed the logging to be more precise.
I needed the logger to match exact table name and the exact column name that the value was saved to. Yes you can do if you have your java entities names mapped to the DB tables and column names, as in the article above.

in the above example if you have Table called TEST_TABLE, the extracted value that will be saved using the audit logger will be TestTable(most likely that will be the name of the class that mapps to the table).
The same will be for the column: FIRST_NAME will be mapped to firstName.
I want to log the column name as it's represented in the DB
So if I have a Column called FIRST_NAME, i want to logged in the DB as FIRST_NAME = Robert.

SO ...Logging it the right way.........
here is what i did

1) DB structure

Action log DB structure, this where i will save all my changes.

Table: ACTION_LOG
Column: ACTION_LOG_ID - > primary key
Column: USER_ID -> number
Column: TABLE_NAME - > varchar
Column: PRIMARY_KEY - > varchar
Column: CONCAT_VALUES- > varchar (values that are saved)
Column: COMMAND -> varchar
Column: TIME_STAMP

Test Entity - This will be my test entity i will try to persist and audit

Table: TEST_TABLE
Column 1: TEST_TABLE_ID -> primary key
Column 2: FIRST_NAME-> varchar2
Column 3: POSITION - > varchar2

2) Hibernate Mappings (using annotations)

Hibernate mapping of ACTION_LOG

@Entity
public class ActionLog implements Serializable {
private static final long serialVersionUID = -9176091358716821364L;
private Long logId;
private Long userId;
private Timestamp timeStamp;/
private String tableName;
private String pkColumn;
private String command;
private String concatValues;

Hibernate mapping for TEST_TABLE

@Entity
public class TestTable
private String firstName;
private String position;
private Long testTableId;

3) Create logger DAO and Service
I use layered architecture in my application, so I create a DAO and a service for the ActionLog class which i will use in my logger when i persist my data.

You will notice that my actionLog DAO is empty. All my basic methods for saving/updating/deleting are located in my base class that the DAO is extanding.

public interface ActionLogService {

void createActionLog(ActionLog actionLog);
}

public class AuditLogServiceImpl implements ActionLogService{

@Autowired
private AuditLogDao auditLogDao;

public AuditLogServiceImpl () {
}

public void createActionLog (ActionLog actionLog) {
auditLogDao.add (actionLog);
}

}


public interface ActionLogDao {}

@Repository("auditLogDAO")
public class AuditLogDAOImpl extends BaseDAOHibImpl implements AuditLogDao {}

4) Create HibernateInterceptor

We will use the hibernate interceptor to log the changes.
As you can see we log on :
onFlushDirty
onSave
onDelete

Every time you try to perform a hibernate update, save or delete one of the methods will run and checks if an audit needs to be done

Couple things to notice that i have here
1)user_id, currently it's set to -1. I save this value in my db logger.
In my code implementation I inject a session bean that holds the user id
2)I use annotations to register my bean

@Service("hibernateInterceptor")
public class HibernateInterceptor extends EmptyInterceptor implements ApplicationContextAware{

private static final long serialVersionUID = -3073850856829239762L;

@Autowired
@Qualifier("commonsActionLogger")
private ActionLogger theLogger;

private ApplicationContext context;

/**
* Creates a new instance of HibernateLoggingInterceptor
*/
public HibernateInterceptor () {
}

public boolean onLoad (Object entity, Serializable id, Object[] state, String[] propertyNames, Type[] types) throws CallbackException {
return false;
}

public boolean onFlushDirty(Object entity, Serializable id, Object[] newValues, Object[] oldValues, String[] propertyNames, Type[] types) throws CallbackException {
if (!(entity instanceof LogStopper)){
theLogger.logThis ("Update",entity,propertyNames,getUserId());
}

return false;
}

private Long getUserId() {
return -1L;
}


public boolean onSave (Object entity, Serializable id, Object[] state, String[] propertyNames, Type[] types) throws CallbackException {
if (!(entity instanceof LogStopper)){
theLogger.logThis ("Create",entity,propertyNames,-getUserId());
}
return false;
}


public void onDelete (Object entity, Serializable id, Object[] state, String[] propertyNames, Type[] types) throws CallbackException {
if (!(entity instanceof LogStopper)){
theLogger.logThis ("Delete",entity,propertyNames,getUserId());
}
}

public void setApplicationContext(ApplicationContext arg0)
throws BeansException {
this.context=arg0;

}
}

5)Register the intercept

Register the following property in your sessionFactory

property name="entityInterceptor" ref="hibernateInterceptor"

6) Create THE LOGGER
Here is the fun stuff, here is where we hack in to the session factory and extract data so we can parse out the DB info so we can save the data

I have 2 classes and 1 interface here
AtionLoggecr interface
DatabaseActionLoger -> this is where i save the audited entity to the DB
ParseHibEntity - This is a util class where i hack in to the session factory and get all the info i need to save the audited entity ( I get the table info and the value that is persisted)

public interface ActionLogger {

void logThis (String command, Object entity, String[] properties,Long userId) ;

}

public class DatabaseActionLogger implements ActionLogger{

@Autowired
private ActionLogService actionLogService;

public void logThis(String command, Object entity, String[] properties,Long userId) {

if (!(entity instanceof ActionLog)){

//new actionlog
ActionLog actionLog = new ActionLog();

//prse object, get all the methods
ParseHibEntity phe = new ParseHibEntity(entity,properties);


//set command and table name
actionLog.setCommand(command);
actionLog.setTableName(phe.extractTableName());

//primary key column
actionLog.setPkColumn(phe.extractPrimaryKeyColumn());

//save all contact values
actionLog.setConcatValues(phe.extractColumnValues());

//set time stemp
actionLog.setTimeStamp(new Timestamp(new Date().getTime()));
actionLog.setUserId(userId);

//save the actionlog
actionLogService.createActionLog(actionLog);

}

}
}

public class ParseHibEntity {
private Logger log = Logger.getLogger(this.getClass());
private PersistentClass pc = null;
private Object entity;
private String[] properties;

public static final String DATE_FORMAT = "yyyy-MM-dd";
public static final String DATE_TIME_FORMAT = "yyyy-MM-dd hh:mm:ss a";
/**
* Creates a new instance of ParseHibEntity
*/
public ParseHibEntity(Object entity, String[] properties) {
this.pc = extractPersistentClass(entity.getClass().getName());
this.entity = entity;
this.properties = properties;
}

private PersistentClass extractPersistentClass(String entityName){
PersistentClass pc = null;
LocalSessionFactoryBean sessionFactory = null;
try {
sessionFactory = (LocalSessionFactoryBean)AppCtxHolder.getApplicationContext().getBean("&mySessionFactory");
pc = ((LocalSessionFactoryBean)sessionFactory).getConfiguration().getClassMapping(entityName);
}catch(NullPointerException npe){
log.error("NullPointerException - make sure you get the right session factory " + npe.getMessage(),npe);
}
return pc;
}

public String extractPrimaryKeyValue(){
//Get pk column and value
String pkValue = null;
try{
pkValue = pc.getIdentifierProperty().getGetter(entity.getClass()).get(entity).toString();
}catch(PropertyNotFoundException pnfe){
log.info("PropertyNotFoundException " + pnfe.getMessage());
}catch(MappingException me){
log.info("MappingException " + me.getMessage());
}catch(HibernateException he){
log.info("HibernateException " + he.getMessage());
}catch(NullPointerException npe){
log.info("NullPointerException " + npe.getMessage());
}

return pkValue;
}

public String extractPrimaryKeyColumn(){
String pkColumn = null;
try{
pkColumn = ((Column)pc.getIdentifierProperty().getColumnIterator().next()).getName();
}catch(NullPointerException npe){
log.info("NullPointerException " + npe.getMessage());
}

return pkColumn;
}

public String extractPrimaryKeyColumn(PersistentClass localPC){
String pkColumn = null;
try{
pkColumn = ((Column)localPC.getIdentifierProperty().getColumnIterator().next()).getName();
}catch(NullPointerException npe){
log.info("NullPointerException " + npe.getMessage());
}

return pkColumn;
}

public String extractPrimaryKeyValue(PersistentClass localPC, Object localEntity){
//Get pk column and value
String pkValue = null;
try{
pkValue = localPC.getIdentifierProperty().getGetter(localEntity.getClass()).get(localEntity).toString();
}catch(PropertyNotFoundException pnfe){
log.error("PropertyNotFoundException " + pnfe.getMessage(),pnfe);
}catch(MappingException me){
log.error("MappingException " + me.getMessage(),me);
}catch(HibernateException he){
log.error("HibernateException " + he.getMessage(),he);
}catch(NullPointerException npe){
log.error("NullPointerException " + npe.getMessage(),npe);
}

return pkValue;
}

@SuppressWarnings("unchecked")
public String extractColumnValues(){
StringBuffer sb = new StringBuffer();

//add the pk column and value
sb.append(extractPrimaryKeyColumn() + " = " + extractPrimaryKeyValue() + " | ");
//System.out.println("pc.getProperty (scale) " + pc.getProperty ("scale"));


//loop through all the other properties and get what you need
for (String p: properties){
Property pr = pc.getProperty(p);

//make sure that this is not a collection and not a one to one as these values are not part of the table
if (!pr.getType().isCollectionType() && !(pr.getType() instanceof OneToOneType)){

//make sure that the values are persistent values and not a forumla value
if (pr.isInsertable() || pr.isUpdateable()) {
int scale = 2;

//get the getter for the entity
Getter getter = pr.getGetter(entity.getClass());

//get column value
Object columnValue = getter.get(entity);

//get column name
for (Iterator it3 = pr.getColumnIterator(); it3.hasNext(); ) {
Column column = (Column)it3.next();
sb.append(column.getName());
scale = column.getScale();
}

sb.append(" = ");

//check what kind of type of value this is, it if it an association then get the forign key value from the associated entity
if (columnValue != null){
if (!pr.getType().isAssociationType()){

//if bigD set Scale
if (columnValue instanceof BigDecimal){
columnValue = ((BigDecimal)columnValue).setScale(scale,BigDecimal.ROUND_HALF_DOWN);
}else if (columnValue instanceof java.util.Date){
SimpleDateFormat sdf = null;
if(columnValue instanceof java.sql.Timestamp){
sdf = new SimpleDateFormat(DATE_TIME_FORMAT);
}else{
sdf = new SimpleDateFormat(DATE_FORMAT);
}
columnValue = sdf.format(columnValue);
} else if (pr.getType().getName().equalsIgnoreCase("org.springframework.orm.hibernate3.support.ClobStringType")){
columnValue = "Clob Value";
}

sb.append(columnValue);
}else{
//since it's an association we know that column value is an object
String associatedEntityName = pr.getType().getName();
//associatedEntityName = ((EntityType)pr.getType()).getAssociatedEntityName ();
PersistentClass localPC = extractPersistentClass(associatedEntityName);
String fkValue = extractPrimaryKeyValue(localPC,columnValue);
sb.append(fkValue);
}
}


sb.append(" | ");
}
}
}
return sb.toString();
}

public String extractTableName(){
try {
return pc.getTable().getName();
}catch(NullPointerException npe){
log.error("NullPointerException - table is null " + npe.getMessage(),npe);
return "";
}
}

}

7)Using IT
No all you have to do is persit you data, so if you do the following

TestDAO.save(TestEntity):
the logger will save save the following if no in the ACTION_LOG

LOG_ID = 1
USER_ID = -1
TABLE_NAME = TEST TABLE
PRIMARY_KEY = 1
CONCAT_VALUES = FIRST_NAME = JavaRobski | POSITIONS = Architect
COMMAND = SAVE
TIME_STAMP = 2008-09-01