Tuesday, January 13, 2009

Auditing with OpenJPA

A transactional application often requires to audit the persistent entities. In this brief example, I will present a small code example to outline how an application can audit changes via the life cycle callback methods. The JPA specification prescribes how an entity or a separate, stateless entity listener instance can receive callback notification during various life cycle state transition of an entity. Seven transition events are defined: PrePersist, PostPersist, PreRemove, PostRemove, PreUpdate, PostUpdate and PostLoad. To receive these callbacks either annotate certain methods a) of the entity class itself or b) of a separate entity listener class. The signature of the method in the entity class itself should be

void <METHOD>()
Whereas, callback methods defined on an entity listener class have the following signature
void <METHOD>(Object pc)
In the later case, the managed entity is passed as an argument.

Given this basic framework, how can we implement audit facility such that an application can track any update made on a persistent entity? Of course, to compute this change, the application must be able to access the entity state before and after the update. The central question is:


how can an application access the previous state of an entity inside a callback method?

The answer lies in the fact that OpenJPA can store the state of an entity as it enters the managed lifecycle. This internal copy is used by OpenJPA when a transaction is rolled back. The state of the entities participating in the failed transaction is restored to the original state i.e. as it were before the transaction started. The simple example presented here shows how to access that copy. Of course, a real audit facility has to figure out how to compute the difference between the current and previous state of an entity and where to record those differences.

Let us consider a simple persistent instance, audit.PObject.
   1:  package audit;
2:
3: import javax.persistence.Entity;
4: import javax.persistence.Id;
5: import javax.persistence.PostUpdate;
6:
7: import org.apache.openjpa.enhance.PersistenceCapable;
8: import org.apache.openjpa.kernel.SaveFieldManager;
9: import org.apache.openjpa.kernel.StateManagerImpl;
10:
11: @Entity
12: public class PObject {
13: @Id
14: private long id;
15:
16: private String name;
17:
18: public long getId() {
19: return id;
20: }
21:
22: public void setId(long id) {
23: this.id = id;
24: }
25:
26: public String getName() {
27: return name;
28: }
29:
30: public void setName(String name) {
31: this.name = name;
32: }
33:
34: @PostUpdate
35: public void audit() {
36: PersistenceCapable currentState = (PersistenceCapable)this;
37: StateManagerImpl sm = (StateManagerImpl)currentState.pcGetStateManager();
38: SaveFieldManager sfm = sm.getSaveFieldManager();
39: PersistenceCapable oldState = sfm.getState();
40: PObject old = (PObject)oldState;
41:
42: System.err.println("old : " + old);
43: System.err.println("current : " + this);
44: }
45:
46: public String toString() {
47: return this.getClass().getName()+"@"
48: + Integer.toHexString(System.identityHashCode(this))
49: + "[" + name +"]";
50: }
51: }
The meat is in audit() method annotated with @PostUpdate to receive the callback notification. Now, within the method body, following steps are carried out to access the previous state of the instance.

Line 36: Cast this instance to org.apache.openjpa.enhance.PersistenceCapable interface. The cast is safe. Because OpenJPA ensures that every persistent class implements PersistenceCapable. OpenJPA actually modifies original bytecode of audit.PObject class. This bytecode modification process is called enhancement and is described in detail in OpenJPA documentation.

Line 37: Get the StateManager. Every PersistenceCapable instance is managed by a StateManager. It is the StateManager who intercepts every access and mutation of entity state and calls the requisite underlying OpenJPA infrastructure to load or store the state of an entity which in turn may access the database via JDBC.

Line 38: Get the SaveFieldManager. A StateManager may refer to a SaveFieldManager to which StateManager delegates the task of maintaining a copy of managed instance.

Line 39: Get the old state. The old state is maintained by the SaveFieldManager.

Line 40: Cast is back to audit.PObject. This entity refers to the state of PObject as it entered a transaction.

At this point, a real audit application perhaps will do some sort of state comparison to determine what has changed between current and the previous state of this instance. I am just printing their values on the console.

Now let us write a simple "Hellow JPA World" style application to check that the callback is received. I am omitting the scaffolding code to get a JPA EntityManagerFactory etcetera and just listing the transactional method.


   1:      public void testPostPersistCallabck() {
2: EntityManager em = emf.createEntityManager();
3: em.getTransaction().begin();
4: PObject pc = new PObject();
5: pc.setId(1001);
6: pc.setName("X");
7: em.persist(pc);
8: em.getTransaction().commit();
9: Object pid = pc.getId();
10: em.clear();
11:
12: em = emf.createEntityManager();
13: em.getTransaction().begin();
14: PObject audit = em.find(PObject.class, pid);
15: audit.setName("Y");
16: em.getTransaction().commit();
17: }
When this code runs on my laptop against a MySQL database, that is what it prints out (hand-edited to show only the generated SQL and System.err.println() output)
203  test  INFO   [main] openjpa.jdbc.JDBC - Using dictionary class "org.apache.openjpa.jdbc.sql.MySQLDictionary".
1078 test TRACE [main] openjpa.jdbc.SQL - <t 21933769, conn 11875256> executing prepstmnt 7245716 INSERT INTO PObject (id, name) VALUES (?, ?) [params=(long) 1001, (String) X]
1156 test TRACE [main] openjpa.jdbc.SQL - <t 21933769, conn 23978087> executing prepstmnt 1440568 SELECT t0.name FROM PObject t0 WHERE t0.id = ? [params=(long) 1001]
1172 test TRACE [main] openjpa.jdbc.SQL - <t 21933769, conn 14837200> executing prepstmnt 30702379 UPDATE PObject SET name = ? WHERE id = ? [params=(String) Y, (long) 1001]

old : audit.PObject@1581e80[X]
current : audit.PObject@3a9d95[Y]
As the last two lines of log output shows, the audit() callback has been invoked and the method had printed the state of the instance as it were before its name is changed from "X" to "Y".
The two critical points before we close.
  • This technique only works with build-time enhancement.
  • OpenJPA must be configured to record the state of persistent entities participating in a transaction. This is specified by the following property:
            <property name="openjpa.RestoreState" value="all"/>
 
 

18 comments:

Lens said...

hello,

I was trying to use JPA with Websphere and MySql with J2EE and I keep getting
A JDBC Driver or DataSource class name must be specified in the ConnectionDriverName property.

the persistece looks like:


persistence-unit name="test"
jta-data-source jdbc/test /jta-data-source
class
tables.Address /class
properties
property name="openjpa.jdbc.Schema" value="test" /

property name="openjpa.ConnectionFactoryProperties" value="PrettyPrint=true,PrettyPrintLineLength=80" /
!--
property name="openjpa.Log" value="DefaultLevel=TRACE,Tool=TRACE"
/
--
/properties
/persistence-unit
/persistence


both the RAD connection and the websphere connection jdbc/test work when I try to just test the connection outside the program.


Have you ever managed to acieve that or it's not possible?


Cheers,
Adrian

Kevin Sutter said...

Lens,
When a <jta-data-source> is specified, OpenJPA will attempt to do the global jndi lookup for this datasource first. If that lookup fails, then OpenJPA attempts to use the openjpa.Connection* properties to resolve the datasource. So, in this case, it looks like the lookup of the "jdbc/test" data-source is not working.

You mention that the datasource works in RAD and the "websphere connection". In the latter, are you referring to doing the test connection from within the WebSphere admin console?

Are you attempting to use the datasource from a Java EE application (ear or war)? If you have the proper bindings in your application, you may actually have a local (component) level jndi name for this datasource. Something like "java:comp/env/jdbc/test".

From your application, you should be able to do the jndi lookup using the name provided in your <jta-data-source> element. If that doesn't work, then OpenJPA won't be able to get access either. It's a straight forward lookup operation.

You might also want to consider Tracing this process to find out whether the problem is in the configuration or WebSphere or OpenJPA. The trace spec for OpenJPA is "openjpa=all=enabled".

What you are attempting should work just fine. I just don't think we have enough information to figure out the source of the problem yet.

Kevin

Karan Singh Malhi said...

I tried setting up the trace level to openjpa=all=enabled
nothing shows up on the console.

Here is my trace setting
*=info:openjpa=all=enabled

I need help to enable logging and view SQL statements.

Kevin Sutter said...

The trace setting mentioned (openjpa=all=enabled) is for the WebSphere environment. When this trace setting is specified, the trace output from OpenJPA will be merged with the normal trace output of the WebSphere Application Server. So, under default configurations, the OpenJPA trace output will be merged with the log file in this location:

c:\WebSphere\AppServer\profiles\AppSrv01\logs\server1

If you are not running within WebSphere, then you will need to set your trace settings for OpenJPA via your persistence.xml file. In this case, you will need a property setting along these lines:

<property name="openjpa.Log" value="DefaultLevel=TRACE" />

More information on logging in general can be found in the InfoCenter:

http://publib.boulder.ibm.com/infocenter/wasinfo/v7r0/topic/com.ibm.websphere.express.doc/info/exp/ae/tejb_loggingwjpa.html

Hope this helps,
Kevin

Karan Singh Malhi said...

Thanks Kevin,

I was able to achieve to get the trace to trace.log. I am working with RAD 7.5 and was wondering if there is a way to redirect the trace output to the console view. I know that System.out logs can be viewed in the console, do you know if there is something similar for trace logs?

Kevin Sutter said...

Good. I'm glad that you got your trace output to trace.log, at least. As far as redirecting this to your console within RAD, I'm not aware of that ability. I checked with one on my experts and it sounds like you already had a similar conversation with him (Mike) on FreeNode... :-)

Thanks,
Kevin

Karan Singh Malhi said...

Really really wish Websphere was not intercepting the logging mechanism with its own tracing annoyance.
Thanks for the help though. Each time I run a query, will have to reload the trace.log file to see the SQL, whereas a simple redirect to the console would have made development and testing so much easier.

Kevin Sutter said...

Hi,
I can understand your frustration, but we're kind of stuck in a hard place on this one. In the container-managed environment, if WebSphere didn't intercept the trace settings, then a developer's persistence.xml could wreak havoc on a production system.

One approach that we suggest quite often is to test your Entities outside of a container-managed environment. Since you are interested in seeing which SQL is being produced, the same SQL will be generated whether the Entities are used within or outside of a container. Granted, you might need an alternative driver to test the Entities, but the ease of unit testing outside of a container may be worth the effort.

Kevin

mnilson said...

I am attempting a slightly more sophisticated auditing solution than you have outlined here. Perhaps you can tell me I'm doing a bad thing.

I have two entities Entity and EntityAudit. EntityAudit has all fields of Entity plus some audit info (ie datetime, user, etc). In a PostUpdate lifecycle method of Entity I am using OpenJPAPersistence.getEntityManager(this); to grab an entity manager and call persist against it passing the newly constructed EntityAudit that contains essentially an audit snapshot of Entity.

First of all this doesn't actually work. OpenJpa issues an update statement against the Entity table and issues a select statement against the EntityAudit table and no insert into the Audit table. After seeing Pinaki's post in this thread http://n2.nabble.com/Updates-to-entities-via-Lifecycle-callback-methods-td1110631.html I am almost positive this is a bad idea.

I guess I am looking for suggestions on alternatives. I'm not happy with the idea of a service method that all updates to my entity would have to pass through because that is really only suitable when an entity has been detached and is being brought back into context. Right now I'm leaning towards db triggers and I'm sure that will lead to issues with jpa caching; I would definately prefer to stay with a jpa-only solution.

thanks,
Mike

( H@n|)@|\| said...

hello,
I aint able to get "System.out" and "System.err" messages of Java file
in SystemOut or SystemErr log of WebSphere. I am getting all kind of server messages in log files but i m not getting the print message of System.err or System.out in log files. What changes i should do to get that messages?

Kevin Sutter said...

Hi ( H@n|)@|\|,
By default, WebSphere should be intercepting the System.out and System.err println's and redirecting them to the SystemOut or SystemErr log files. No additional configuration should be required to make this happen. If this is not working as desired, I would open a problem report (PMR) with IBM support.

Thanks,
Kevin

Meenakshi Sahu said...

Hi, I am trying to use the Open JPA auditor facility. Currenlty i am on OpenJPA Version 2.2.2. Here is the configuration in my persistence.xml file. And here is the auditor class package com.principal.scbu.ods.audit; import java.util.Collection; import javax.persistence.EntityManager; import org.apache.openjpa.audit.Auditor; import org.apache.openjpa.kernel.Audited; import org.apache.openjpa.kernel.Broker; import org.apache.openjpa.lib.conf.Configuration; public class ChangeControlAuditor implements Auditor { public void audit(Broker broker, Collection newObjects, Collection updates, Collection deletes) { persistChangeControl(newObjects); System.out.println(" \n\n *** AUDIT NEW " + newObjects.size()); System.out.println(" \n\n *** AUDIT UPDATES " + updates.size()); System.out.println(" \n\n *** AUDIT DELETES " + deletes.size()); System.out.println(" \n\n *** AUDIT broker " + broker.getClass().getSimpleName()); } However when i am tyring to add the application to my server it gives the below exception while starting the application. Caused by: org.apache.openjpa.lib.util.ParseException: Instantiation of plugin "Auditor" with value "com.principal.scbu.ods.audit.ChangeControlAuditor" caused an error "java.lang.IllegalArgumentException: java.lang.NoClassDefFoundError: org.apache.openjpa.audit.Auditor". The alias or class name may have been misspelled, or the class may not have be available in the class path. Valid aliases for this plugin are: [default] at org.apache.openjpa.lib.conf.Configurations.getCreateException(Configurations.java:422) at org.apache.openjpa.lib.conf.Configurations.newInstance(Configurations.java:222) at org.apache.openjpa.lib.conf.ObjectValue.newInstance(ObjectValue.java:124) at org.apache.openjpa.lib.conf.PluginValue.instantiate(PluginValue.java:105) at org.apache.openjpa.lib.conf.ObjectValue.instantiate(ObjectValue.java:83) at org.apache.openjpa.conf.OpenJPAConfigurationImpl.getAuditorInstance(OpenJPAConfigurationImpl.java:1833) at org.apache.openjpa.kernel.AbstractBrokerFactory.postCreationCallback(AbstractBrokerFactory.java:861) at org.apache.openjpa.jdbc.kernel.JDBCBrokerFactory.postCreationCallback(JDBCBrokerFactory.java:105) at com.ibm.ws.persistence.jdbc.kernel.WsJpaJDBCBrokerFactory.postCreationCallback(WsJpaJDBCBrokerFactory.java:198) at org.apache.openjpa.kernel.Bootstrap.newBrokerFactory(Bootstrap.java:67) ... 128 more Caused by: java.lang.IllegalArgumentException: java.lang.NoClassDefFoundError: org.apache.openjpa.audit.Auditor at serp.util.Strings.toClass(Strings.java:164) at serp.util.Strings.toClass(Strings.java:108) at org.apache.openjpa.lib.conf.Configurations.newInstance(Configurations.java:214) ... 136 more }

Kevin said...

Hi Meenakshi,
Your post didn't format very well, so it was a little difficult to read. You might want to try posting to the OpenJPA users mailing list [1], just to help with the formatting. And, there may be a larger Auditing audience there.

But, from what it looks like you are experiencing a classloader issue. The "missing" Auditor class is part of the normal OpenJPA artifacts. What is your environment? Are you running OpenJPA standalone in a JSE environment? Or, as part of WebSphere? Or, some other app server? What version of the app server are you using?

Good luck,
Kevin

[1] http://openjpa.apache.org/mailing-lists.html

Meenakshi Sahu said...

Hi All,

I am trying to leverage the OpenJPA2.2.2 auditor feature in my project.

And this really works fine when i use the non-jta transaction.

However once i switch to jta tarnsaction it dosen't works at all. The auditor dosen't gets invoked.

I think my auditor class is perfectly fine because it does works with the non-jta transaction however with the jta transaction it dosen't gets invoked at all.

Does anyone has any idea if we can use the OpenJPA 2.2.2 auditor with the JTA transactions as well or its not feasible at all.

Here is my persistence.xml file.





org.apache.openjpa.persistence.PersistenceProviderImpl
jdbc/SCBUODSCSSDataSource














Meenakshi Sahu said...

Also i am not able to autowire any Spring beans inside the OpenJPA2.2.2 auditor and the reason it seems is the Auditor gets instantiated by the persistence so we are not able to inject any spring beans inside the auditor.
Does any one has does any Dependency injection inside the OpenJPA 2.2.2 auditor.

kwsutter said...

Hi Meenakshi,
Auditing should work just fine with JTA transactions as well as non-JTA transactions. Your posting of the persistence.xml file didn't work very well. I would suggest turning on trace to see if you can determine why your auditing facility is not getting invoked (or at least check your logs for any unexpected errors).

Also, as my previous reply suggested, you might want to post the OpenJPA Users mailing list to get a larger population reading your question(s).

Thanks, Kevin

Meenakshi Sahu said...





org.apache.openjpa.persistence.PersistenceProviderImpl
jdbc/SCBUODSCSSDataSource















Meenakshi Sahu said...

Hi Kevin thanks for your post.

I tried to look into the logs however there is nothing in the app and the server logs.

Also i would like to mention that my application is working perfecting fine upto persisting the things in tables however the auditor dosen't gets invoked.