On buffers, listeners, and pain

We’re working on an application right now that needs to log a number of events: user login, object deletion, and all sorts of other things that are conveniently dispatched through the Spring application context that’s part of the core of Grails.

“Easy enough,” I say to myself.

I whip up a quick service…

> grails create-service AuditService

…and give it a nice method named createAuditEvent( Map params ) that lets you shove a bunch of conveniently-named params onto an instance of an AuditedEvent domain model. It then tacks on a few other standard bits – username, IP address, date/time, and so on – and then saves the instance of AuditedEvent.

I then knocked together a quick Spring event listener (DataAccessAuditingListener) that listens for likely events, such as PreDeleteEvent or SaveOrUpdateEvent, calling auditService.createAuditEvent() with appropriate “stuff.”

Tests pass, a quick smoke test of the UI shows it working, and I commit. The next day, I get a message from another developer:

Uh, Joe, trying to delete() a Foo is giving me this:

org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [foo#21]

It seemed to happen only when auditing was turned on, so I took the blame and dug in. The problem soon became pretty obvious. (If you already know what it is, feel free to stop reading now.) Here’s what was going on, with the “things you don’t do explicitly that Hibernate, Spring and Grails do for you” in italics.

1. A controller would call fooInstance.delete()
2. An internal Hibernate action that deletes the Foo instance would go into Hibernate’s buffer
3. Spring would dispatch a PreDeleteEvent, which my DataAccessAuditingListener would handle, calling auditService.createAuditEvent()
4. The AuditService would create, populate, and save an instance of AuditEvent
5. Because services are implicitly transactional, a commit would occur! Hibernate would therefore flush its buffer, deleting the Foo!!
6. The “rest” of delete() would execute, saying “Hey, Hibernate, it’s cool to delete now!”
7. Hibernate would say “I can’t delete that. Something already flushed a buffer that deleted it.”(or, “Row was updated or deleted by another transaction…”)

My solution? There’s only one persistence operation in createAuditEvent(), so I just turned transactionality off for AuditService.