Bug: configuration_pkey failure in pixeldata

[jamoore]

2013-01-16 05:19:21,808 ERROR [  ome.services.pixeldata.PixelDataThread] (2-thread-2) ExceptionException!
ome.conditions.ValidationException: PreparedStatementCallback; SQL [insert into configuration (name, value) values (?,?)]; ERROR: duplicate key value violates unique
 constraint "configuration_pkey"; nested exception is org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "configuration_pkey"
        at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.doTranslate(SQLErrorCodeSQLExceptionTranslator.java:241)
        at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:72)
        at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:602)
        at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:811)
        at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:867)
        at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:875)
        at org.springframework.jdbc.core.simple.SimpleJdbcTemplate.update(SimpleJdbcTemplate.java:249)
        at ome.util.actions.PostgresSqlAction.setCurrentEventLog(PostgresSqlAction.java:229)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:592)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
        at ome.util.SqlAction$LoggingSqlAction.invoke(SqlAction.java:74)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
        at $Proxy4.setCurrentEventLog(Unknown Source)
        at ome.services.eventlogs.PersistentEventLogLoader.setCurrentId(PersistentEventLogLoader.java:95)
        at ome.services.eventlogs.PersistentEventLogLoader.getCurrentId(PersistentEventLogLoader.java:82)
        at ome.services.pixeldata.PersistentEventLogLoader.query(PersistentEventLogLoader.java:61)
        at ome.services.eventlogs.EventLogLoader.hasNext(EventLogLoader.java:137)
        at ome.services.pixeldata.PixelDataHandler.loadNext(PixelDataHandler.java:108)
        at ome.services.pixeldata.PixelDataHandler.doWork(PixelDataHandler.java:81)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)

[mtbcarroll]

Any clues how to trigger this?

[mtbcarroll]

setCurrentEventLog clearly expects to be isolated from other updates to the configuration table, but at first glance it seems to be called only from PixelDataHandler.loadNext() which looks to be a synchronized method of a singleton bean.

[mtbcarroll]

I should mention that, as well as the PersistentEventLogLoader used by the pixelDataHandler bean, there also seems to be one used by the fullTextIndexer bean, but they are set with different keys so their queries/updates shouldn't clash.

[mtbcarroll]

I wondered if perhaps the problem is that _jdbc().update(logLoaderUpdateSql, id, key) returns 0 if the key is in the table but already has the desired ID, but repeated calls of setCurrentId with the same ID, both outside and inside the same transaction, don't seem to cause any such errors.

[jamoore]

​https://github.com/openmicroscopy/openmicroscopy/pull/1512 opened with a minor (unrelated) change.

Mark: I think you are right that somehow the UPDATE is returning a 0 despite the row being present, but I wouldn't think it would be because the value is already set. I'm happy to add a try/catch for the duplicate key and re-try the update. It's not a clean solution, but might be better than nothing.

[mtbcarroll]

Your minor unrelated change seems to delete the whole method that throws the exception. Is there anything further that I should do on this ticket?

[jamoore]

Well, it removes the shadowing methods from the subclass (PostgresSqlAction) so that the methods in SqlAction.Impl are used.But they were identical.

The only question is if we try to do something preventative even if we can't (yet) reproduce.

[mtbcarroll]

Ohh, right. (-: As the etiology remains a mystery, I'd probably want to avoid a loop in case there's some lasting state in which the update count stays zero but inserts also fail, but how about I catch the exception around the insert and in that case do a warn-level log and retry the update?

[jamoore]

Exactly. I'd definitely avoid a loop.

[mtbcarroll]

Suggested code added by ​https://github.com/openmicroscopy/openmicroscopy/pull/1528

Not sure if we want to close or push this ticket.

[jamoore]

A follow-up ticket would be valid, but since we haven't really done much in the way of reproducibility or fixing this, I guess let's just push it. Thanks, Mark.

[jamoore]

Moving out of 4.4.9. This may become a non-issue if the pixel data thread is re-worked, but if not, we will need to re-evaluate. See the performance issues outlined in PR 1528 (currently closed).

[spli]

OMERO-merge-stable-ice34 logs

[spli]

OMERO-stable-ice34

[mtbcarroll]

Bug observed in current 5.0 merge build (approximately RC3) integration testing.

[jamoore]

CC'ing JB in case any of his indexer investigations have touched on this. Certainly his PR to use a file rather than the DB would fix this.

[jballanco-x]

Could be related to #11993 . Will have to compare the way transactions are set up between the pixel data service and the indexer. Changes in progress for the PersistentEventLogLoader? (as well as future work on the firehose) will definitely work around this.

[jamoore]

See also:
​http://lists.openmicroscopy.org.uk/pipermail/ome-users/2014-April/004401.html

[mtbcarroll]

See also: ​http://lists.openmicroscopy.org.uk/pipermail/ome-users/2014-October/004845.html

[jamoore]

With a number of reports submitted, it would be good to consider this a blocker lest it become a processor-like embarrassment.

[jamoore]

Won't be getting to this for 5.1.0. (I also think this may have been taken care of by previous work from Mark)

[jamoore]

Does anyone know the last time this was seen? Rather than try to figure this out for 5.1.1, I'm going to focus the rest on my time on bumping Hibernate with the hope that that will help anyway.

[jamoore]

Haven't seen in some time. De-prioritizing.