Audit Logging Plugin

Integration tests with auditable domain class do not observe test transaction boundary

Details

  • Type: Bug Bug
  • Status: Closed Closed
  • Priority: Critical Critical
  • Resolution: Duplicate
  • Affects Version/s: None
  • Fix Version/s: None
  • Component/s: None
  • Labels:
    None

Description

Creating a simple domain class with one string field that must be unique fails to observe the transaction boundary of tests if the domain class is marked as auditable.

This worked in Grails 1.2.0, but broke when I tried to upgrade to 1.3.2.

The domain class is simply:

class User {

    String name
    
    static auditable = true

    static constraints = {
        name(unique:true)
    }
}

And test:

void testUser1() {
        def user = new User( name: 'UniqueName' )
        user.save(failOnError:true)
    }
    
    void testUser2() {
        def user = new User( name: 'UniqueName' )
        user.save(failOnError:true)
    }

I've added testable code for Grails 1.3.2 and 1.2.0

Attachments

Issue Links

This issue relates to:
GRAILS-5725 Allow plugins to easily insert hibernate event listeners Major Closed
This issue is related to:
GPAUDITLOGGING-9 audit-logging breaks deletes in grails 1.3.X (grails hibernate-plugin 1.3X) Critical Resolved
GRAILS-6272 Upgrading to grails 1.3 causes tests to fail due to unique constraint errors Critical Closed
This issue depends on:
GPAUDITLOGGING-14 AuditLogEvent domain object fails to save on PostgreSQL and Oracle databases Major Closed

Activity

Ascending order - Click to sort in descending order
Hide
Permalink
Shawn Hartsock added a comment -

Could this be related to: http://jira.codehaus.org/browse/GRAILS-6272 in some way? Since the tests pass in 1.2.0 but fail in 1.3.2 it seems marginally related.

Show
Shawn Hartsock added a comment - Could this be related to: http://jira.codehaus.org/browse/GRAILS-6272 in some way? Since the tests pass in 1.2.0 but fail in 1.3.2 it seems marginally related.
Hide
Permalink
Michael Cameron added a comment -

Yes, it is directly related to that ticket, but that ticket was assigned to core Grails and marked as closed with resolution "cannot reproduce". I think it's still undetermined where the root cause is, but the proximate cause is the Audit-Logging plugin with an auditable domain class. The defect breaks tests that work under 1.2.0, and the only workaround I'm aware of to fix the situation would be to have a custom tearDown() that manually cleans up data (like functional tests). Ideally, the root cause can be addressed, and auditable domain classes can be used in integration tests without manually cleaning up data.

Show
Michael Cameron added a comment - Yes, it is directly related to that ticket, but that ticket was assigned to core Grails and marked as closed with resolution "cannot reproduce". I think it's still undetermined where the root cause is, but the proximate cause is the Audit-Logging plugin with an auditable domain class. The defect breaks tests that work under 1.2.0, and the only workaround I'm aware of to fix the situation would be to have a custom tearDown() that manually cleans up data (like functional tests). Ideally, the root cause can be addressed, and auditable domain classes can be used in integration tests without manually cleaning up data.
Hide
Permalink
Shawn Hartsock added a comment -

So if I'm reading you right you want me to find a way to work around a bug in the core grails architecture?

Show
Shawn Hartsock added a comment - So if I'm reading you right you want me to find a way to work around a bug in the core grails architecture?
Hide
Permalink
Michael Cameron added a comment - - edited

No, if it is a core grails issue then it should be solved there. I don't know that anyone has determined if the bug is in Audit-Logging or core Grails. What is known is that integration tests are still wrapped in a transaction boundary in 1.3.2 and that functionality works correctly. Then, if Audit-Logging is used and a domain class is set to be auditable, an integration test using that domain class no longer has data rolled back after the test. So on the surface it appears to be an audit-logging issue.

I don't know enough of audit-logging or core grails implementations to know if it is a defect in either one, or it is an insurmountable problem given semantic changes with the JUnit 4 upgrade in Grails 1.3.x.

Show
Michael Cameron added a comment - - edited No, if it is a core grails issue then it should be solved there. I don't know that anyone has determined if the bug is in Audit-Logging or core Grails. What is known is that integration tests are still wrapped in a transaction boundary in 1.3.2 and that functionality works correctly. Then, if Audit-Logging is used and a domain class is set to be auditable, an integration test using that domain class no longer has data rolled back after the test. So on the surface it appears to be an audit-logging issue. I don't know enough of audit-logging or core grails implementations to know if it is a defect in either one, or it is an insurmountable problem given semantic changes with the JUnit 4 upgrade in Grails 1.3.x.
Hide
Permalink
Shawn Hartsock added a comment -

This is somewhat problematic. I can't imagine how to make this plugin do any less without using GRAILS-5725 any change such as GRAILS-5725 would require a rewrite that would completely destroy backwards compatibility.

Show
Shawn Hartsock added a comment - This is somewhat problematic. I can't imagine how to make this plugin do any less without using GRAILS-5725 any change such as GRAILS-5725 would require a rewrite that would completely destroy backwards compatibility.
Hide
Permalink
Shawn Hartsock added a comment -

GRAILSPLUGINS-391 is directly related to this issue. Any fix must be careful not to regress GRAILSPLUGINS-391

Show
Shawn Hartsock added a comment - GRAILSPLUGINS-391 is directly related to this issue. Any fix must be careful not to regress GRAILSPLUGINS-391
Hide
Permalink
Shawn Hartsock added a comment -

GRAILS-5725 is a fix for registering handlers of this kind. This issue is the type of issue registered handlers will potentially run into.

Show
Shawn Hartsock added a comment - GRAILS-5725 is a fix for registering handlers of this kind. This issue is the type of issue registered handlers will potentially run into.
Hide
Permalink
Fredrik Aubert added a comment -

Seems to me the audit-logging plugin will persist your domain-objects even if you rollback your transaction. I don't know why - perhaps does the audit-logger start it's own transaction, which will reference your domain object and persist them anyways.

app.grails.version=1.3.4
plugins.audit-logging=0.5.3

pseudocode:

User.withTransaction { tx ->
tx.setRollbackOnly()
new User(name:'test').save()
}

and the user is persisted to the database. When removing audit-logging plugin, things works as expected.

Does this mean that I cannot use audit-logger plugin if I have any use for transactions at all...?

Show
Fredrik Aubert added a comment - Seems to me the audit-logging plugin will persist your domain-objects even if you rollback your transaction. I don't know why - perhaps does the audit-logger start it's own transaction, which will reference your domain object and persist them anyways. app.grails.version=1.3.4 plugins.audit-logging=0.5.3 pseudocode: User.withTransaction { tx -> tx.setRollbackOnly() new User(name:'test').save() } and the user is persisted to the database. When removing audit-logging plugin, things works as expected. Does this mean that I cannot use audit-logger plugin if I have any use for transactions at all...?
Hide
Permalink
Shawn Hartsock added a comment -

It should mean audit log events occur in separate transactions due to GRAILSPLUGINS-391 if you can point out a technique that does not require creation of a separate transaction I will change the plugin to work that way. So far the problem described here seems to occur with integration tests only.

AFAIK this problem starts to show up with Grails 1.3.x as I'm not currently using Grails 1.3.x and this behavior wasn't present in 1.2.x I'm under the impression something changed in Grails. I could be wrong. I've not had the time to invest in this yet.

Show
Shawn Hartsock added a comment - It should mean audit log events occur in separate transactions due to GRAILSPLUGINS-391 if you can point out a technique that does not require creation of a separate transaction I will change the plugin to work that way. So far the problem described here seems to occur with integration tests only. AFAIK this problem starts to show up with Grails 1.3.x as I'm not currently using Grails 1.3.x and this behavior wasn't present in 1.2.x I'm under the impression something changed in Grails. I could be wrong. I've not had the time to invest in this yet.
Hide
Permalink
Fredrik Aubert added a comment -

No, it's not in integration tests only.

I got this in actual application code. When I set rollbackOnly on a transaction, the data is still persisted.

I don't know the internals of either audit-logger plugin, nor grails/gorm. But my guess is that even if I roll back my transaction, audit-logger plugin still has a reference to my domain objects, and commits regardless of the status of my transaction. And when it does so, the domain objects which it references are committed also, even if they were not supposed to.

Unfortunately I do not have any suggestions for a technique which will not require a separate transaction - I'm really not an expert on any of this.

At the end of the day it seems to me that this problem renders the audit-logging plugin useless in grails 1.3.X - regardsless of where the blame is to be placed. If I'm right, and if there's no way to fix this, at least you should update the plugins home page to warn users of 1.3.X that they should not use the plugin.

Show
Fredrik Aubert added a comment - No, it's not in integration tests only. I got this in actual application code. When I set rollbackOnly on a transaction, the data is still persisted. I don't know the internals of either audit-logger plugin, nor grails/gorm. But my guess is that even if I roll back my transaction, audit-logger plugin still has a reference to my domain objects, and commits regardless of the status of my transaction. And when it does so, the domain objects which it references are committed also, even if they were not supposed to. Unfortunately I do not have any suggestions for a technique which will not require a separate transaction - I'm really not an expert on any of this. At the end of the day it seems to me that this problem renders the audit-logging plugin useless in grails 1.3.X - regardsless of where the blame is to be placed. If I'm right, and if there's no way to fix this, at least you should update the plugins home page to warn users of 1.3.X that they should not use the plugin.
Hide
Permalink
Shawn Hartsock added a comment -

Just out of curiosity have you tried this with Grails 1.2 ?

Show
Shawn Hartsock added a comment - Just out of curiosity have you tried this with Grails 1.2 ?
Hide
Permalink
Fredrik Aubert added a comment -

Well, I did use this on grail 1.2, and I just upgraded to 1.3.4. I do not recall having this problem on 1.2. And I know I did test it - and I'm quite sure I did test it when I had the audit-logging plugin installed (but not 100% positive). So I think it does work as expected in 1.2.

I guess it is the same problem as with the integration tests, as I assume the integration tests does the same thing; starts a transaction and sets it to rollback only.

Show
Fredrik Aubert added a comment - Well, I did use this on grail 1.2, and I just upgraded to 1.3.4. I do not recall having this problem on 1.2. And I know I did test it - and I'm quite sure I did test it when I had the audit-logging plugin installed (but not 100% positive). So I think it does work as expected in 1.2. I guess it is the same problem as with the integration tests, as I assume the integration tests does the same thing; starts a transaction and sets it to rollback only.
Hide
Permalink
Shawn Hartsock added a comment -

BTW: looking at this event handler code (the thing which makes the logging possible)...

public boolean onPreDelete(final PreDeleteEvent event) {
try {
def audit = isAuditableEntity(event)
String[] names = event.getPersister().getPropertyNames()
Object[] state = event.getDeletedState()
def map = makeMap(names, state)
if (audit && !callHandlersOnly(event.getEntity())) { def entity = event.getEntity() def entityName = entity.getClass().getName() def entityId = getEntityId(event) logChanges(null, map, null, entityId, 'DELETE', entityName) }
if (audit) { executeHandler(event, 'onDelete', map, null) }
} catch (HibernateException e) { log.error "Audit Plugin unable to process DELETE event" e.printStackTrace() }
return false
}

... I can't spot anywhere that there's a reference to the entity that shouldn't be garbage collected. Which is why I can't logically reason out how to fix this bug. I'm going to try putting calls to "clone()" everywhere but that shouldn't matter. I could place a finally that explicitly set the entity reference to null... but that shouldn't matter...

Show
Shawn Hartsock added a comment - BTW: looking at this event handler code (the thing which makes the logging possible)... public boolean onPreDelete(final PreDeleteEvent event) { try { def audit = isAuditableEntity(event) String[] names = event.getPersister().getPropertyNames() Object[] state = event.getDeletedState() def map = makeMap(names, state) if (audit && !callHandlersOnly(event.getEntity())) { def entity = event.getEntity() def entityName = entity.getClass().getName() def entityId = getEntityId(event) logChanges(null, map, null, entityId, 'DELETE', entityName) } if (audit) { executeHandler(event, 'onDelete', map, null) } } catch (HibernateException e) { log.error "Audit Plugin unable to process DELETE event" e.printStackTrace() } return false } ... I can't spot anywhere that there's a reference to the entity that shouldn't be garbage collected. Which is why I can't logically reason out how to fix this bug. I'm going to try putting calls to "clone()" everywhere but that shouldn't matter. I could place a finally that explicitly set the entity reference to null... but that shouldn't matter...
Hide
Permalink
Shawn Hartsock added a comment -

I want to note...

I have not reproduced this using "grails run-app" and manually testing it. I have reproduced the bug when using integration tests. I considered this a less than major issue since I thought people were only seeing this in test but not production.

Show
Shawn Hartsock added a comment - I want to note... I have not reproduced this using "grails run-app" and manually testing it. I have reproduced the bug when using integration tests. I considered this a less than major issue since I thought people were only seeing this in test but not production.
Hide
Permalink
Michael Cameron added a comment -

We saw this in production as well with 1.3.2 and audit-logging. It turned up some nasty defects of data hanging around that should not have.

As you and I have discussed via private messages, this appears to be related to semantic changes with transaction handling in grails 1.2.x vs 1.3.x. I don't know if/how audit-logging can be changed to have the behavior of grails 1.2.x+audit logging

We worked around the issue in integration tests and production by monkey patching audit logging. Specifically:

def monkeyPatchAuditLogListener(applicationContext) {
    def auditLogListener = applicationContext.getBean('auditLogListener')
    //fix listener overwriting
    auditLogListener.metaClass.addListener = {Object[] array ->
        def expanded = new Object[(array?.length?:0) + 1]
        if(array)
            System.arraycopy(array, 0, expanded, 0, array.length)
        expanded[-1] = auditLogListener
        return expanded
    }

    //fix transaction issue
    def sessionFactory = applicationContext.getBean('sessionFactory')
    auditLogListener.saveAuditLog = { AuditLogEvent audit ->
        audit.with {
            dateCreated = new Date()
            lastUpdated = new Date()
        }
        try {
            Session session = sessionFactory.openSession()
            log.trace "opened new session for audit log persistence"
            //def trans = session.beginTransaction()
            //log.trace " + began transaction "
            def saved = session.merge(audit)
            log.debug " + saved log entry id:'${saved.id}'."
            session.flush()
            log.trace " + flushed session"
            //trans.commit()
            //log.trace " + committed transaction"
            session.close()
            log.trace "session closed"
        } catch (org.hibernate.HibernateException ex) {
          log.error "AuditLogEvent save has failed!"
          log.error ex.message
          log.error audit.errors
        }
        return
    }
}

I think you added the transaction stuff to fix Oracle specific issues, but it clearly is causing some bad side effects with MySql (and others?) in grails 1.3.x

Show
Michael Cameron added a comment - We saw this in production as well with 1.3.2 and audit-logging. It turned up some nasty defects of data hanging around that should not have. As you and I have discussed via private messages, this appears to be related to semantic changes with transaction handling in grails 1.2.x vs 1.3.x. I don't know if/how audit-logging can be changed to have the behavior of grails 1.2.x+audit logging We worked around the issue in integration tests and production by monkey patching audit logging. Specifically: 
def monkeyPatchAuditLogListener(applicationContext) {
    def auditLogListener = applicationContext.getBean('auditLogListener')
    //fix listener overwriting
    auditLogListener.metaClass.addListener = {Object[] array ->
        def expanded = new Object[(array?.length?:0) + 1]
        if(array)
            System.arraycopy(array, 0, expanded, 0, array.length)
        expanded[-1] = auditLogListener
        return expanded
    }

    //fix transaction issue
    def sessionFactory = applicationContext.getBean('sessionFactory')
    auditLogListener.saveAuditLog = { AuditLogEvent audit ->
        audit.with {
            dateCreated = new Date()
            lastUpdated = new Date()
        }
        try {
            Session session = sessionFactory.openSession()
            log.trace "opened new session for audit log persistence"
            //def trans = session.beginTransaction()
            //log.trace " + began transaction "
            def saved = session.merge(audit)
            log.debug " + saved log entry id:'${saved.id}'."
            session.flush()
            log.trace " + flushed session"
            //trans.commit()
            //log.trace " + committed transaction"
            session.close()
            log.trace "session closed"
        } catch (org.hibernate.HibernateException ex) {
          log.error "AuditLogEvent save has failed!"
          log.error ex.message
          log.error audit.errors
        }
        return
    }
}
I think you added the transaction stuff to fix Oracle specific issues, but it clearly is causing some bad side effects with MySql (and others?) in grails 1.3.x
Hide
Permalink
Fredrik Aubert added a comment -

If you would like to see it with grails:run-app, I guess all you will have to do is create code like this:

User.withTransaction { tx -> 
tx.setRollbackOnly() 
new User(name:'test').save() 
}

Run against mysql.

This should mean that the user is not created in the db. If the user object is persisted, then there's a bug.

I've tried this with hsqldb, mysql and postgres to see if it were a db specific bug before I tried to run without the audit-logging plugin, and it ran just as it should (tested only with mysql and hsqldb).

Show
Fredrik Aubert added a comment - If you would like to see it with grails:run-app, I guess all you will have to do is create code like this: 
User.withTransaction { tx -> 
tx.setRollbackOnly() 
new User(name:'test').save() 
}
Run against mysql. This should mean that the user is not created in the db. If the user object is persisted, then there's a bug. I've tried this with hsqldb, mysql and postgres to see if it were a db specific bug before I tried to run without the audit-logging plugin, and it ran just as it should (tested only with mysql and hsqldb).
Hide
Permalink
Shawn Hartsock added a comment -

The problem was caused by my use of a transaction when saving the auditLog object. In summary the listener used to do this:

Session session = sessionFactory.openSession()
def trans = session.beginTransaction()
def saved = session.merge(auditLogObject)
session.flush()
trans.commit()
session.close()

I've added code to turn on and off the calls to the transaction based on either the application mode or Config.groovy settings. Not using a transaction means the tests pass. However, many transactional databases will probably prefer the use of the transaction and since some developers may use real databases in test (or not) I've made this a setting.

Show
Shawn Hartsock added a comment - The problem was caused by my use of a transaction when saving the auditLog object. In summary the listener used to do this: Session session = sessionFactory.openSession() def trans = session.beginTransaction() def saved = session.merge(auditLogObject) session.flush() trans.commit() session.close() I've added code to turn on and off the calls to the transaction based on either the application mode or Config.groovy settings. Not using a transaction means the tests pass. However, many transactional databases will probably prefer the use of the transaction and since some developers may use real databases in test (or not) I've made this a setting.
Hide
Permalink
Shawn Hartsock added a comment -

Fix will be in 0.5.4

Show
Shawn Hartsock added a comment - Fix will be in 0.5.4

People

Vote (3)
Watch (4)

Dates

  • Created:
    Updated:
    Resolved:
Atlassian JIRA (v4.4.1#660-r161644) | Report a problem
Powered by a free Atlassian JIRA open source license for Grails project. Try JIRA - bug tracking software for your team.