I have a problem that's just baffling me and I'm hoping it rings a bell with someone.

I have a SortedSet of events, here's the .hbm snippet.
<set name="events" table="CAPTURE_EVENT" cascade="all" sort="natural">

I only ever add to the set, I never delete. The events are added when my finite state machine moves through states. The state machine is syncronized, there is never a case where two separate threads will simultaenous add events to the SortedSet. Each event starts a Hibernate transaction and commits it when the event has been processed. No sub-threads are spawned while processing the event. Each time an event comes in a copy of the object holding the SortedSet of events is read from the database (I'm not caching anything manually).

What's baffling me is most of the time I see Hibernate insert a row for a new event, which is expected. Occassionally (1 out of 5 or 6 times) it will add the new event AND delete a previous event. Again, my code never deletes from the SortedSet so this delete is undesired. Here's some snippets of the SQL:

- enter FSM
2005-03-14 09:05:00,226 [TaskExecutorService-2] INFO STDOUT Hibernate: insert into PACKAGER.CAPTURE_EVENT (CAPTURE_ID, OCCURRED_AT, EVENT_TYPE, SEVERITY, MESSAGE) values (?, ?, ?, ?, ?)
2005-03-14 09:05:00,226 [TaskExecutorService-2] INFO STDOUT Hibernate: update PACKAGER.CAPTURE_FSM_STATE_NAMES set STATE_NAME=? where CAPTURE_ID=? and VIDEO_SERVER=?
- exit FSM
- enter FSM
2005-03-14 09:05:00,319 [TaskExecutorService-3] INFO STDOUT Hibernate: delete from PACKAGER.CAPTURE_EVENT where CAPTURE_ID=? and OCCURRED_AT=? and EVENT_TYPE=? and SEVERITY=? and MESSAGE=?
2005-03-14 09:05:00,335 [TaskExecutorService-3] INFO STDOUT Hibernate: insert into PACKAGER.CAPTURE_EVENT (CAPTURE_ID, OCCURRED_AT, EVENT_TYPE, SEVERITY, MESSAGE) values (?, ?, ?, ?, ?)
- exit FSM

Now, you can see it's two different threads (TaskExecutorService-2 and TaskExecutorService-3), but one waits for the other to finish.

I've spent about 3 days trying to figure it out and I'm absolutely stumped. I realize this isn't a tremendous amount to go on, but hopefully someone will recognize the problem and know the cause.

I've tried searching through the form and haven't found anything quite like it.

This smells like a hashcode/equals implementation problem.

Have you provided an implementation for these methods in the objects that are in the set?

Here's the methods. I use the Jakarta Commons EqualsBuiler and HashcodeBuilder. There's never a time when where two different objects should return equal as the message is never the same twice at the same time.

private Date _occurredAt;
private CaptureEventType _eventType;
private SeverityType _severity;
private String _message;

public boolean equals(Object o) {
if (o == null) return false;
if (!(o instanceof CaptureEvent)) return false;

CaptureEvent ce = (CaptureEvent) o;
return new EqualsBuilder()
.append(_occurredAt, ce._occurredAt)
.append(_eventType.getId(), ce._eventType.getId())
.append(_severity.getId(), ce._severity.getId())
.append(_message, ce._message).isEquals();
}

public int hashCode() {
return new HashCodeBuilder()
.append(_occurredAt)
.append(_eventType.getId())
.append(_severity.getId())
.append(_message).toHashCode();

Well, with hibernate logging at maximum I can see the SQL deletion taking place. It's unclear why it's making that choice though. Anyone understand what causes a SortedSet to decide if something needs to be deleted?

After lots of debugging, it really looks like something is fishy in SortedSet. I have a hard time believing it's a bug since I'm sure others use it, but I'm at a loss to understand what I'm doing wrong. Here's an excerpt of my logging. As you can see, I add an event then persist. This is 7th event that's been added, the previous 6 having been fine and just cause the expected insert. This one causes a delete, but I don't understand why. I've spewed out the list contents immediately after the add and immediately before the transaction persists and they are identical.

What's causing Hibernate to think it should delete an entry? It's the same code path each time that adds the event and persists, nothing different about this persist than the last 6 as far as code path executions.

Please, any ideas?

TRACE scheduledcapture Added a new event
TRACE scheduledcapture Event is Created
TRACE scheduledcapture Event is Provisioning successful
TRACE scheduledcapture Event is Capture start for vssix failed, will retry...
TRACE scheduledcapture Event is Capture start for vsseven failed, will retry...
TRACE scheduledcapture Event is Capture successfully started on vsthree
TRACE scheduledcapture Event is Capture start for vseight failed, will retry...
TRACE scheduledcapture Event is Capture successfully started on vstwo
TRACE scheduledcapture About to save...
TRACE scheduledcapture Event list is:
TRACE scheduledcapture Event is Created
TRACE scheduledcapture Event is Provisioning successful
TRACE scheduledcapture Event is Capture start for vssix failed, will retry...
TRACE scheduledcapture Event is Capture start for vsseven failed, will retry...
TRACE scheduledcapture Event is Capture successfully started on vsthree
TRACE scheduledcapture Event is Capture start for vseight failed, will retry...
TRACE scheduledcapture Event is Capture successfully started on vstwo
TRACE hibernate com.ncube.nable.app.packager.scheduledcapture.ScheduledCaptureService save(): Entering
TRACE hibernate com.ncube.nable.app.packager.scheduledcapture.ScheduledCaptureService save(): Exiting
DEBUG hibernate Committing database transaction of this thread.
INFO STDOUT Hibernate: delete from PACKAGER.CAPTURE_EVENT where CAPTURE_ID=? and OCCURRED_AT=? and EVENT_TYPE=? and SEVERITY=? and MESSAGE=?
INFO STDOUT Hibernate: insert into PACKAGER.CAPTURE_EVENT (CAPTURE_ID, OCCURRED_AT, EVENT_TYPE, SEVERITY, MESSAGE) values (?, ?, ?, ?, ?)
INFO STDOUT Hibernate: update PACKAGER.CAPTURE_FSM_STATE_NAMES set STATE_NAME=? where CAPTURE_ID=? and VIDEO_SERVER=?

BTW, this is the event it's deleting. There doesn't appear to be any consistency in what it chooses to delete (ie. not always the last added, or first added, etc).

TRACE scheduledcapture Event is Capture successfully started on vsthree