Implement Database Audit Log with LightSpeed Entity

Hey,

I'm trying to use LightSpeed to implement database audit log feature. I want to save all details to log tables and put all logic in base class.

I would like to know what is the best way to do this in LightSpeed.

My simple testing model:
DbObject <- DbCodeName <- Company (all concrete inheritance)

And then I override OnSaving in DbObject:

        protected override void OnSaving(CancelEventArgs e)
        {
            if (LogEnabled)
            {
                //Get Action Insert/Update/Delete: From EntityState
                //Get Table Name/Entity Name: by Reflection?
                //Save to Log header table using current UnitOfWorks

                //Get all Properties' original values and new values: by Reflection?
                //Save to Log details table using current UnitOfWorks
            }
            base.OnSaving(e);
        }

My questions are:
1) What's the best way to get Fields/Properties list, original values and new values?
I didn't find any exposed method which can get such information.
Or I missed something?

2) Will the entities added in OnSaving be saved in same transaction of current entity?

Many Thanks
Wicky

1. We don't store the original values of entity properties -- we only store whether an entity is dirty (the Modified state).  You would need to do this yourself, for example when loading the entity by overriding AfterLoad.  You can find out which properties have changed either by doing a comparison or by overriding OnPropertyChanged to log them as they change (note that you *MUST* call the base class implementation of OnPropertyChanged if you do this).

2. I don't think these entities will be part of the same transaction, because LightSpeed assembles a list of entities that need saving *before* it calls OnSaving for each such entity.  Entities created within OnSaving will not be on the list, and will therefore not be included in the SaveChanges.  You would need to do another SaveChanges when all the "real" saves are complete, and that would by default happen in its own transaction.  (Of course you could explicitly wrap both SaveChanges calls in your own transaction.)  But see note 2 below.

A couple of things to watch out for though:

1. OnSaving does not appear to be called for Deleted entities.  I think this may be a bug though.

2. We would recommend extreme caution attempting to create "log record" entities and save them within the OnSaving method.  There are two concerns here.  First, you may get an infinite regress, as OnSaving is called for the "log record" entities.  Second, you may see erratic behaviour because of the ordering of save processing.  At present, I think any "log record" entities you add to the unit of work will not get saved as part of the save in progress, because LightSpeed has already assembled the list of entities that need saving.  However this is definitely an internal implementation detail and you should not rely on it.  We recommend against doing anything that would change the state of the UOW within the lifecycle events.

I suggest a possible better approach might be to create your log records within overrides of OnPropertyChanged and OnEntityStateChanged (for deletes), so that by the time you get round to saving everything, the log records are all constructed, added to the UOW and ready to go, and just get committed automatically when the unit of work is saved.

Hi, Ivan,

Thank you for your prompt and professional answers as always.
I'll try your suggestions.

Thanks again,
Wicky

Hi, Ivan,

I didn't find way to get fields list/properties list in AfterLoad.

Do I need to use Reflection and then get all public properties, but ignore property which has Transient attribute? Or there is any other rule?

As I remember, DevExpress XPO has a ClassInfo property in base Entity class which provide such information. It will be usefull if something similar in LightSpeed Entity.

Thanks
Wicky

Yes, you would need to use reflection (and note that Transient and most other attributes are applied to fields, not properties).  We don't expose the LightSpeed metamodel.  This is being discussed for 3.0, though given resource constraints I suspect it is more likely to be a post-3.0 feature.

Hi, Ivan,

After some studying and testing, I can get Fields list now.
And I found some issues of the implementation:

1. AfterLoad event:
If I put backup logic in AfterLoad, every entity will have a copy of data in memory, for all kind of queries.
But what I want is to load original values for Update action of some important entities. So it seems it takes too much resources for just audit log. I think it's better to reload data from database when Update action happens. I get information from this post How do I disable caching?, which indicated I could force to reload data in a new UnitofWork, but I didn't try it yet.

2. EntityStateChanged event
For new entity, it occurs once when unitOfWork.SaveChanges called, from EntityState from New to Default;
For editing entity, it occurs two times, first time is property changed, from Default to Modified, second time is when calling unitOfWork.SaveChanges, from Modified to Default;
For deleting entity, it occurs two times, first time when unitOfWork.Remove, from Default to Deleted, second time when unitOfWork.SaveChanges, from Deleted to Default;

So what I can capture is Delete action (from Default to Deleted). For other actions, as discussed, they happened in SaveChanges so couldn't be in same transaction if I add log records, right?.

3. PropertyChanged event
It will happen several times if user amend the same field several time before click Save.
So several log records might be added even user just save once.

After all, what I want to save is just final state (which persist to database), not the value changes in the middle.

I hope I explain my situation clearly and appreciate for your valuable input.

Thanks
Wicky

1. If you want to audit only certain changes, you have two options:

(1) Log the original state of all entities in AfterLoad, but emit a log record only for "interesting" changes.  This will have the overhead of doubling the size of every entity, but this only matters if you have a substantial number of large entities -- if you only have a few dozen entities with a few dozen fields then the additional storage is just not worth worrying about.

(2) When you see an "interesting" change, reload the original entity data into a copy.  As you note, this would have to be done in a separate unit of work, but that's easy enough to do.  The downside of this approach is that it results in additional database round-trips, but if you have lots of entities and relatively few actions that require audit then this may be a good trade-off.

2. It depends what you want to audit.  If you want to audit changes, you should just be able to sit on PropertyChanged.  You could also sit on EntityStateChanged and watch for when the entity goes into Modified (this will happen as soon as a change is made; it doesn't wait for SaveChanges)  If you want to audit deletions, you will need to monitor EntityStateChanged and create a log record when the entity goes from Default to Deleted.  If you want to audit inserts, you can't use EntityStateChanged, but PropertyChanged should do the job unless someone creates a new entity and leaves all properties as their default values (or you can just have the entity constructor emit a log record).

3. Yes, PropertyChanged fires each time a property changes, which could result in the event being raised multiple times for the same property before the object is saved.  But this just means you can't just keep naively adding log records to the unit of work: you also need to keep a dictionary or something, so that if a property changes twice, you can update the existing log record rather than adding a new one.

Hi, Ivan,

Your suggestions are logical but seems need to do and maintain lots of things.

I would like to back to my original thinkings:

  protected override void OnSaving(CancelEventArgs e)
        {
            if (LogEnabled)
            {
                //Get Action Insert/Update/Delete: From EntityState
                //Get Table Name/Entity Name: by Reflection?
                //Save to Log header table using current UnitOfWorks

                //Get all Properties' original values and new values: by Reflection?
                //Save to Log details table using current UnitOfWorks

               Switch(EntityState) {
                   case New:
                        generate new log records
                   case Modified:
                        retrieve original data by Id from database
                        generate update log records
                   case Deleted:
                        generate deleted records
                }
            }
            base.OnSaving(e);
        }

 The logic is simple and easy to control, the issues might be:
1) Could I get the proper status?
2) Delete not fire event? (bug?)
3) Not same Transaction? Is it possible to use same transaction for two UnitOfWork?
Or can I attach additional entities to current unitOfWork without firing further events?

If above issues can be solved and the method seems more easy to understand and maintain.
Anyway, just some thinkings about how to use LightSpeed.

Regards
Wicky

Sorry, more accurate Point 3):

3) Not same Transaction? Is it possible to use same transaction for two UnitOfWork?
Or can I attach additional entities to current unitOfWork which can be processed in current batch
and without firing further events (this can be controlled in user code indeed, just disable audit for log related entity)?

1. You should be able to get the proper status (assuming you are referring to the entity state).  If you are not seeing the correct status then this may indicate a bug -- if you can give us a repro case then we can look into it.

2. We can address this for you if required, so that OnSaving fires for deletes.  Note however that OnSaving will NOT fire for cascade deletes, because the entities being cascade-deleted may not even have been materialised (e.g. if a parent object has a dependent lazy-loaded collection, and the parent is deleted without the children having been loaded -- the children will be deleted out of the database but will not be materialised as entities).

3. Once again, we would strongly advise against trying to add entities into the unit of work during the save cycle.  A better idea if you want to do the logging during the save cycle might be:

* In the calling code, begin a transaction (using BeginTransaction() or a TransactionScope.
* Call IUnitOfWork.SaveChanges().
* In OnSaving, create the log records but do not add them to the unit of work.
* After SaveChanges returns, add the log records to the unit of work.
* Call IUnitOfWork.SaveChanges().
* Commit the transaction.

The log records will not be saved as part of the same batch but they will be saved within the same transaction.

If you are using a Repository-type pattern, which hides the unit of work object from the application code, then you can of course encapsulate all of this within your Repository.SaveChanges method so as to ensure that application code can't "forget" to save the logs.

Hi, Ivan,

1. I tried and the states are ok (except Deleted of course).

2. Please do it and Thank you!

3. I will try it. I think this is an acceptable solution.

In theory I totally agree with you about the concerns for changing entities within OnSaving.
But in practice, I prefer to violate the rule to allow doing this as special case, suppose to take additional entities into list or something, which will be processed after normal entities, within same transaction, and no further events. Maybe it's not good in theory but easy and convenient for use. Anyway, it's just my personal opinion.

Thanks for your advices again.
Wicky

I've added code to call OnSaving for deletes, and this will be included in nightly builds dated 13 Mar 2009 and above, available from about 1430 GMT.

In theory, I agree with your "in practice."  But in practice, there's a significant complexity cost if we can't assume that the set of changes is stable during the save cycle.