NHibernate: Updating collections during EventListener “PreUpdateEvent”

Question

I'm trying to write an audit tracking for Nhibernate that hooks into the PreUpdate event. I have an AuditLogEntry class (when, who, etc), that contains a list of AuditLogEntryDetails (i.e. individual properties that changed). If I isolate the AuditLogEntry class from the entity being audited then my code runs with no errors. However, if I add a list of AuditLogEntry's to the entity being audited then my code throws a

collection [DomainObjects.AuditTracking.AuditLogEntry.Details] was not processed by flush()

assertion failure when I attempt to save the modified list inside the event listener. This only happens when the audited item already has one (or more) AuditLogEntry instance in the list. If there are no entries then a new list is created and added to the entity being audited and this is fine.

I think by isolating the issue to the above it would appear to be around (lazy) loading the existing list to add the new instance of AuditLogEntry too. However I've been unable to progress any further. Adding 'Lazy="False"' to the list mapping doesn't appear to help. I'm really in the early days of using NHibernate, having borrowed concepts from both the HN 3.0 Cookbook and this blog post. My code is very similar to this, but attempts to add the audit history to the item being audited in a list (and as such I think that I need to also do that in the pre, rather than post update event).

A snap shot of the entity interfaces/classes in question are:

public class AuditLogEntry : Entity
{
    public virtual AuditEntryTypeEnum AuditEntryType { get; set; }
    public virtual string EntityFullName { get; set; }
    public virtual string EntityShortName { get; set; }
    public virtual string Username { get; set; }
    public virtual DateTime When { get; set; }
    public virtual IList<AuditLogEntryDetail> Details { get; set; }
}

public interface IAuditTrackedEntity
{
    Guid Id { get; }
    IList<AuditLogEntry> ChangeHistory { get; set; }
}

public class AuditTrackedEntity : StampedEntity, IAuditTrackedEntity
{
    public virtual IList<AuditLogEntry> ChangeHistory { get; set; }
} 

public class LookupValue : AuditTrackedEntity
{
    public virtual string Description { get; set; }
}

For the mappings I have:

AuditTrackedEntry.hbm.xml:

<?xml version="1.0" encoding="utf-8" ?>
<hibernate-mapping xmlns="urn:nhibernate-mapping-2.2" assembly="DomainObjects" namespace="DomainObjects.AuditTracking">
  <class name="AuditLogEntry">
    <id name="Id">
      <generator class="guid.comb" />
    </id>
    <version name="Version" />
    <property name="AuditEntryType"/>
    <property name="EntityFullName"/>
    <property name="EntityShortName"/>
    <property name="Username"/>
    <property name="When" column="`When`"/>
    <list name ="Details" cascade="all">
      <key column="AuditLogEntryId"/>
      <list-index column="DetailsIndex" base="1"/>
      <one-to-many class="AuditLogEntryDetail"/>
    </list>
  </class>
</hibernate-mapping>

lookupvalue.hbm.xml:

<?xml version="1.0" encoding="utf-8" ?>
<hibernate-mapping xmlns="urn:nhibernate-mapping-2.2" assembly="DomainObjects" namespace="DomainObjects">
  <class name="LookupValue">
    <id name="Id">
      <generator class="guid.comb" />
    </id>
    <discriminator type="string">
      <column name="LookupValueType" unique-key="UQ_TypeName" not-null="true" />
    </discriminator>
    <version name="Version" />
    <property name="Description" unique-key="UQ_TypeName" not-null="true" />
    <property name="CreatedBy" />
    <property name="WhenCreated" />
    <property name="ChangedBy" />
    <property name="WhenChanged" />
    <list name ="ChangeHistory">
      <key column="EntityId"/>
      <list-index column="ChangeIndex" base="1"/>
      <one-to-many class="DomainObjects.AuditTracking.AuditLogEntry"/>
    </list>
  </class>
</hibernate-mapping>

The EventListener PreUpdate event handler calls the follow code: The lines that cause the problem are commented near the end of the code block

    public void TrackPreUpdate(IAuditTrackedEntity entity, object[] oldState, object[] state, IEntityPersister persister, IEventSource eventSource)
    {
        if (entity == null || entity is AuditLogEntry)
            return;

        var entityFullName = entity.GetType().FullName;
        if (oldState == null)
        {
            throw new ArgumentNullException("No old state available for entity type '" + entityFullName +
                                            "'. Make sure you're loading it into Session before modifying and saving it.");
        }

        var dirtyFieldIndexes = persister.FindDirty(state, oldState, entity, eventSource);
        var session = eventSource.GetSession(EntityMode.Poco);

        AuditLogEntry auditLogEntry = null;
        foreach (var dirtyFieldIndex in dirtyFieldIndexes)
        {
            if (IsIngoredProperty(persister, dirtyFieldIndex))
                continue;

            var oldValue = GetStringValueFromStateArray(oldState, dirtyFieldIndex);
            var newValue = GetStringValueFromStateArray(state, dirtyFieldIndex);

            if (oldValue == newValue)
            {
                continue;
            }
            if (auditLogEntry == null)
            {
                auditLogEntry = new AuditLogEntry
                                    {
                                        AuditEntryType = AuditEntryTypeEnum.Update,
                                        EntityShortName = entity.GetType().Name,
                                        EntityFullName = entityFullName,
                                        Username = Environment.UserName,
                                        //EntityId = entity.Id,
                                        When = DateTime.Now,
                                        Details =  new List<AuditLogEntryDetail>()
                                    };


                //**********************
                // The next three lines cause a problem when included,
                // collection [] was not processed by flush()
                //**********************
                if (entity.ChangeHistory == null)
                    entity.ChangeHistory = new List<AuditLogEntry>();
                entity.ChangeHistory.Add(auditLogEntry);

                session.Save(auditLogEntry);    
            }

            var detail = new AuditLogEntryDetail  
                             {
                                 //AuditLogEntryId = auditLogEntry.Id,
                                 PropertyName = persister.PropertyNames[dirtyFieldIndex],
                                 OldValue = oldValue,
                                 NewValue = newValue
                             };
            session.Save(detail);
            auditLogEntry.Details.Add(detail);

        }

        session.Flush();
    }

As previously stated, in this configuration I get an assertion failure "collection [] was not processed by flush()". If I remove the three lines above and the list mapping in the lookupcode.hmb.xml then everything works as expected, other than the entity being audited no longer contains a reference to it's own audited items.

Answer 1

we were facing very similar problem, exactly same exception, but in different situation. No solution found yet...

We have NH event listener implementing IPreUpdateEventListener and OnPreUpdate method used for audit log. Everything is fine for simple properties updating, dirty checking works well, but there are problems with lazy collections. When updating some object which has lazy collection and accessing any object field in the event listener OnPreUpdate method, the same exception as mentioned above is thrown. When lazy set to false, problem disappears.

So it seems there is some problem with lazy collections (and no influence of collection initialization before saving). Our problem isn't connected with creating new collection items; only reading existing object, only its field accessing from the event listener causes the problem.

So in your case, maybe, lazy set to false only for the associatioon could fix the problem, but on the other hand probably you really want to have the collection to be lazy. So hard to say, if the problem has resolution or IInterceptor have to be used instead.

Answer 2

Ok, I have found your problem, this line is actually causing the problem.

Details =  new List<AuditLogEntryDetail>()

You can't initialize an empty collection before you save because the EntityPersister will not persist the collection, but it will error that the collection has not been processed.

Also, once nHibernate calls event listeners, cascades do not work (not sure if this is by design or not). So even though you are adding the detail item to the collection later, you are only calling save on the detail, not the parent, so the change is not propagated. I would recommend re-factoring so that items are completed in this order...

Detail, then save,

AuditLogEntry, then save,

Entity, then update.

Answer 3

I had exactly same problem while using EventListener. I was looping through properties one-by-one to detect changes, that included enumerating collections. However when I added a check for the collection using NHibernateUtil.IsInitialized(collection), problem disappeared. I wouldn't catch-and-ignore the AssertionFailure exception since it might have unknown side-effects.

Answer 4

There's an issue still open to solve this problem. There's a patch at the end of topic that solved it to me.

https://nhibernate.jira.com/browse/NH-3226