Notice: In order to edit this ticket you need to be either: a Product Owner, The owner or the reporter of the ticket, or, in case of a Task not yet assigned, a team_member"

Task #10181 (accepted)

Opened 7 years ago

Last modified 4 years ago

Bug: configuration_pkey failure in pixeldata

Reported by: jamoore Owned by: jamoore
Priority: blocker Milestone: Asynchronous
Component: Services Version: 4.4.8
Keywords: n.a. Cc: java@…, jballanco-x
Resources: n.a. Referenced By: n.a.
References: n.a. Remaining Time: n.a.
Sprint: n.a.

Description

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)

Attachments (2)

log-4.4.8-1077-2f17edb-ice34-b238.zip (23.9 MB) - added by spli 6 years ago.
OMERO-merge-stable-ice34 logs
log-4.4.8-973-930afb6-ice34-b373.zip (5.6 MB) - added by spli 6 years ago.
OMERO-stable-ice34

Change History (29)

comment:1 Changed 6 years ago by mtbcarroll

  • Owner changed from jamoore to mtbcarroll
  • Version set to 4.4.8

comment:2 Changed 6 years ago by mtbcarroll

  • Status changed from new to accepted

comment:3 Changed 6 years ago by mtbcarroll

Any clues how to trigger this?

comment:4 Changed 6 years ago by 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.

comment:5 Changed 6 years ago by 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.

comment:6 Changed 6 years ago by 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.

comment:7 Changed 6 years ago by 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.

comment:8 Changed 6 years ago by 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?

comment:9 Changed 6 years ago by 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.

comment:10 Changed 6 years ago by 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?

comment:11 Changed 6 years ago by jamoore

Exactly. I'd definitely avoid a loop.

comment:12 Changed 6 years ago by mtbcarroll

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

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

comment:13 Changed 6 years ago by mtbcarroll

  • Sprint set to Blocker 4.4.9 (1)

comment:14 Changed 6 years ago by jamoore

  • Milestone changed from OMERO-4.4.9 to OMERO-4.4.x
  • Sprint Blocker 4.4.9 (1) deleted

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.

comment:15 Changed 6 years ago by mtbcarroll

  • Owner changed from mtbcarroll to jamoore

comment:16 Changed 6 years ago by 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).

Changed 6 years ago by spli

OMERO-merge-stable-ice34 logs

Changed 6 years ago by spli

OMERO-stable-ice34

comment:17 Changed 6 years ago by mtbcarroll

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

comment:18 Changed 6 years ago by jamoore

  • Cc java@… jballanco-x added; jburel removed

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.

comment:19 Changed 6 years ago by 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.

comment:22 Changed 5 years ago by jamoore

  • Milestone changed from 5.x to 5.1.0
  • Priority changed from critical to blocker

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

comment:23 Changed 5 years ago by jamoore

  • Milestone changed from 5.1.0 to 5.1.1

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)

comment:24 Changed 5 years ago by jamoore

  • Milestone changed from 5.1.1 to 5.1.2

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.

comment:25 Changed 5 years ago by jamoore

  • Milestone changed from 5.1.2 to 5.1.3

comment:26 Changed 4 years ago by jamoore

  • Milestone changed from 5.1.3 to 5.x

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

comment:27 Changed 4 years ago by jamoore

  • Milestone changed from 5.x to Asynchronous
Note: See TracTickets for help on using tickets. You may also have a look at Agilo extensions to the ticket.

1.3.13-PRO © 2008-2011 Agilo Software all rights reserved (this page was served in: 0.136362 sec.)

We're Hiring!