Warning: Can't synchronize with repository "(default)" (/home/git/ome.git does not appear to be a Git repository.). Look in the Trac log for more information.
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 #5749 (closed)

Opened 13 years ago

Closed 12 years ago

BUG: Delete handler ObjectNotExistException

Reported by: atarkowska Owned by: jamoore
Priority: minor Milestone: OMERO-4.4
Component: General Version: n.a.
Keywords: n.a. Cc: cxallan, cneves, jamoore, atarkowska
Resources: n.a. Referenced By: n.a.
References: n.a. Remaining Time: 0.0d
Sprint: 2012-01-17 (6)

Description (last modified by atarkowska)

It happened when project was deleted

Thu, 02 Jun 2011 09:07:14 views-web    ERROR    Traceback (most recent call last):
  File "/home/omero/OMERO.server-4.3.0-DEV-ec9b8cde/lib/python/omeroweb/webclient/views.py", line 1676, in manage_action_c
ontainers
    request.session['callback'][str(handle)] = {'delmany':False, 'did':ids[0], 'dtype':key, 'dstatus':'in progress', 'derror':handle.errors(), 'dreport':_formatReport(handle)}
  File "/home/omero/OMERO.server-4.3.0-DEV-ec9b8cde/lib/python/omero_api_IDelete_ice.py", line 228, in errors
    return _M_omero.api.delete.DeleteHandle._op_errors.invoke(self, ((), _ctx))
ObjectNotExistException: exception ::Ice::ObjectNotExistException
{
    id =
    {
        name = DeleteHandle63c449a7-838c-41a1-98b4-7474285e1e28
        category = 5dc659c2-14bc-4cba-b5e8-5477c2cffc92
    }
    facet =
    operation = errors
}

Attachments (1)

Blitz-0.log​ (208.9 KB) - added by jburel 13 years ago.

Download all attachments as: .zip

Change History (23)

comment:1 Changed 13 years ago by atarkowska

  • Cc cxallan added
  • Description modified (diff)

comment:2 Changed 13 years ago by jmoore

  • Cc cneves-x jmoore added
  • Owner changed from jmoore to atarkowska

It means that the service has been removed from the server, Ola. The ObjectNotExistException should probably be handled centrally.

Could this be related to the session time out issue we've been seeing? Does this always happen? Can you reproduce readily?

comment:3 Changed 13 years ago by cxallan

More information also available on #5745. I've only seen it once on Gretzky Josh and the server recovered right afterwards. Looking in the server log there are various graph related errors, not sure what's up with that. The Python code that's actually calling this is effectively:

handle = gateway.deleteObjects(...)
errors = handle.errors()

Where the object not exist exception is hit on the second line. Very odd race condition.

comment:4 Changed 13 years ago by jmoore

Is it possible that the gateway has moved on to another session? It's closed due to a timeout, which leads to the delete handles being removed.

omero@gretzky:~/OMERO-CURRENT$ grep 5dc659c2-14bc-4cba-b5e8-5477c2cffc92 var/log/Blitz-0.log | grep -E "(DeleteHandle|Timeout|Session)" | grep -v reload
2011-06-02 09:01:04,670 INFO  [ ome.services.blitz.fire.SessionManagerI] (l.Server-2) Found session locally: 5dc659c2-14bc-4cba-b5e8-5477c2cffc92
2011-06-02 09:01:04,671 INFO  [ ome.services.blitz.fire.SessionManagerI] (l.Server-2) Rejoining session ServiceFactoryI(session-4f404d52-5d71-4378-8157-ed88539e566f/5dc659c2-14bc-4cba-b5e8-5477c2cffc92) (agent=OMERO.insight;secure=false)
2011-06-02 09:01:21,149 INFO  [        ome.services.util.ServiceHandler] (3-thread-4)  Executor.doWork -- ome.services.blitz.impl.DeleteHandleI.run(5dc659c2-14bc-4cba-b5e8-5477c2cffc92/DeleteHandlef03f14ee-5a28-49fc-b6fe-1806671e8d5c, size=2)
2011-06-02 09:01:21,150 INFO  [ ome.services.blitz.impl.ServiceFactoryI] (l.Server-4) Added servant to adapter: 5dc659c2-14bc-4cba-b5e8-5477c2cffc92/DeleteHandlef03f14ee-5a28-49fc-b6fe-1806671e8d5c(ome.services.blitz.impl.DeleteHandleI@371f9e38)
2011-06-02 09:01:23,228 INFO  [ ome.services.blitz.impl.ServiceFactoryI] (l.Server-2) Unregistered servant:5dc659c2-14bc-4cba-b5e8-5477c2cffc92/DeleteHandlef03f14ee-5a28-49fc-b6fe-1806671e8d5c(ome.services.blitz.impl.DeleteHandleI@371f9e38)
2011-06-02 09:07:14,681 INFO  [ ome.services.blitz.impl.ServiceFactoryI] (l.Server-4) Added servant to adapter: 5dc659c2-14bc-4cba-b5e8-5477c2cffc92/DeleteHandle63c449a7-838c-41a1-98b4-7474285e1e28(ome.services.blitz.impl.DeleteHandleI@16132e77)
2011-06-02 09:07:14,681 INFO  [        ome.services.util.ServiceHandler] (3-thread-2)  Executor.doWork -- ome.services.blitz.impl.DeleteHandleI.run(5dc659c2-14bc-4cba-b5e8-5477c2cffc92/DeleteHandle63c449a7-838c-41a1-98b4-7474285e1e28, size=1)
2011-06-02 09:07:44,145 INFO  [ ome.services.blitz.impl.ServiceFactoryI] (l.Server-9) Added servant to adapter: 5dc659c2-14bc-4cba-b5e8-5477c2cffc92/DeleteHandle03e0e376-8e91-4711-8c79-53e8f959196d(ome.services.blitz.impl.DeleteHandleI@6ecf3233)
2011-06-02 09:07:44,146 INFO  [        ome.services.util.ServiceHandler] (3-thread-5)  Executor.doWork -- ome.services.blitz.impl.DeleteHandleI.run(5dc659c2-14bc-4cba-b5e8-5477c2cffc92/DeleteHandle03e0e376-8e91-4711-8c79-53e8f959196d, size=1)
2011-06-02 09:36:28,044 INFO  [ome.services.sessions.state.SessionCache] (3-thread-1) Destroying session 5dc659c2-14bc-4cba-b5e8-5477c2cffc92 due to : Timeout
2011-06-02 09:36:28,061 INFO  [ ome.services.blitz.fire.SessionManagerI] (3-thread-1) Reaping 2 clients for 5dc659c2-14bc-4cba-b5e8-5477c2cffc92
2011-06-02 09:36:28,067 INFO  [ ome.services.blitz.impl.ServiceFactoryI] (3-thread-1) Unregistered servant:5dc659c2-14bc-4cba-b5e8-5477c2cffc92/DeleteHandle63c449a7-838c-41a1-98b4-7474285e1e28(ome.services.blitz.impl.DeleteHandleI@16132e77)
2011-06-02 09:36:28,070 INFO  [ ome.services.blitz.impl.ServiceFactoryI] (3-thread-1) Unregistered servant:5dc659c2-14bc-4cba-b5e8-5477c2cffc92/DeleteHandle03e0e376-8e91-4711-8c79-53e8f959196d(ome.services.blitz.impl.DeleteHandleI@6ecf3233)
2011-06-02 09:36:28,072 INFO  [ ome.services.blitz.fire.SessionManagerI] (3-thread-1) Removing ServiceFactoryI(session-4f404d52-5d71-4378-8157-ed88539e566f/5dc659c2-14bc-4cba-b5e8-5477c2cffc92)
2011-06-02 09:36:28,072 INFO  [ ome.services.blitz.fire.SessionManagerI] (3-thread-1) Removing ServiceFactoryI(session-b8652724-d8a9-40ec-aee8-86fc8a3b134d/5dc659c2-14bc-4cba-b5e8-5477c2cffc92)

comment:5 Changed 13 years ago by jburel

  • Sprint changed from 2011-06-02 (13) to 2011-06-16 (14)

Moved from sprint 2011-06-02 (13)

comment:6 Changed 13 years ago by jmoore

As mentioned on devteam, the only lead I really have to go on is that there were three deletes in very short succession:

omero@gretzky:~/OMERO-CURRENT$ grep -E "Project[^\d]*205" var/log/Blitz-0.log | grep -E "(Deleting|Missing)"
2011-06-02 09:07:14,689 INFO  [   ome.services.blitz.impl.DeleteHandleI] (3-thread-2) Deleting /Project:205
2011-06-02 09:07:14,694 WARN  [          ome.services.graphs.GraphState] (3-thread-2) Missing delete 205 from Project: root=205
2011-06-02 09:07:44,154 INFO  [   ome.services.blitz.impl.DeleteHandleI] (3-thread-5) Deleting /Project:205
2011-06-02 09:07:44,157 WARN  [          ome.services.graphs.GraphState] (3-thread-5) Missing delete 205 from Project: root=205
2011-06-02 09:11:51,899 INFO  [   ome.services.blitz.impl.DeleteHandleI] (3-thread-2) Deleting /Project:205

comment:7 Changed 13 years ago by jmoore

This query shows more clearly what went wrong.

omero@gretzky:~/OMERO-CURRENT/var/log$ grep -E "servant.*5dc659c2-14bc-4cba-b5e8-5477c2cffc92.*Handle|Deleting..Project:205" Blitz-0.log

## First servant added AND removed by another thread

2011-06-02 09:01:21,150 INFO  [ ome.services.blitz.impl.ServiceFactoryI] (l.Server-4) Added servant to adapter: 5dc659c2-14bc-4cba-b5e8-5477c2cffc92/DeleteHandlef03f14ee-5a28-49fc-b6fe-1806671e8d5c(ome.services.blitz.impl.DeleteHandleI@371f9e38)
2011-06-02 09:01:23,228 INFO  [ ome.services.blitz.impl.ServiceFactoryI] (l.Server-2) Unregistered servant:5dc659c2-14bc-4cba-b5e8-5477c2cffc92/DeleteHandlef03f14ee-5a28-49fc-b6fe-1806671e8d5c(ome.services.blitz.impl.DeleteHandleI@371f9e38)

## Now, 2 more servants are added, but ** 3 ** calls are made to "Deleting /Project:205"

2011-06-02 09:07:14,681 INFO  [ ome.services.blitz.impl.ServiceFactoryI] (l.Server-4) Added servant to adapter: 5dc659c2-14bc-4cba-b5e8-5477c2cffc92/DeleteHandle63c449a7-838c-41a1-98b4-7474285e1e28(ome.services.blitz.impl.DeleteHandleI@16132e77)
2011-06-02 09:07:14,689 INFO  [   ome.services.blitz.impl.DeleteHandleI] (3-thread-2) Deleting /Project:205
2011-06-02 09:07:44,145 INFO  [ ome.services.blitz.impl.ServiceFactoryI] (l.Server-9) Added servant to adapter: 5dc659c2-14bc-4cba-b5e8-5477c2cffc92/DeleteHandle03e0e376-8e91-4711-8c79-53e8f959196d(ome.services.blitz.impl.DeleteHandleI@6ecf3233)
2011-06-02 09:07:44,154 INFO  [   ome.services.blitz.impl.DeleteHandleI] (3-thread-5) Deleting /Project:205

## My guess is that somehow this is the intended delete from the first servant, but what happened to it for 10 minutes??

2011-06-02 09:11:51,899 INFO  [   ome.services.blitz.impl.DeleteHandleI] (3-thread-2) Deleting /Project:205
2011-06-02 09:36:28,067 INFO  [ ome.services.blitz.impl.ServiceFactoryI] (3-thread-1) Unregistered servant:5dc659c2-14bc-4cba-b5e8-5477c2cffc92/DeleteHandle63c449a7-838c-41a1-98b4-7474285e1e28(ome.services.blitz.impl.DeleteHandleI@16132e77)
2011-06-02 09:36:28,070 INFO  [ ome.services.blitz.impl.ServiceFactoryI] (3-thread-1) Unregistered servant:5dc659c2-14bc-4cba-b5e8-5477c2cffc92/DeleteHandle03e0e376-8e91-4711-8c79-53e8f959196d(ome.services.blitz.impl.DeleteHandleI@6ecf3233)

Is it possible that cancel got called?

comment:8 Changed 13 years ago by jburel

When Delete ROI, I have seen the following

  • Delete one ROI on an image with several ROIs using Delete queue
  • when deletion is completed (finished method in delete Call back(
  • save the rest of the roi (update)
  • The roi/shape are not always deleted and can lead to the following exceptions 
    Cannot Save the ROI for image: 278
	at org.openmicroscopy.shoola.env.data.OMEROGateway.handleException(OMEROGateway.java:873)
	at org.openmicroscopy.shoola.env.data.OMEROGateway.saveROI(OMEROGateway.java:6605)
	at org.openmicroscopy.shoola.env.data.OmeroImageServiceImpl.saveROI(OmeroImageServiceImpl.java:1338)
	at org.openmicroscopy.shoola.env.data.views.calls.ROISaver$1.doCall(ROISaver.java:74)
	at org.openmicroscopy.shoola.env.data.views.BatchCall.doStep(BatchCall.java:144)
	at org.openmicroscopy.shoola.util.concur.tasks.CompositeTask.doStep(CompositeTask.java:226)
	at org.openmicroscopy.shoola.env.data.views.CompositeBatchCall.doStep(CompositeBatchCall.java:126)
	at org.openmicroscopy.shoola.util.concur.tasks.ExecCommand.exec(ExecCommand.java:165)
	at org.openmicroscopy.shoola.util.concur.tasks.ExecCommand.run(ExecCommand.java:274)
	at org.openmicroscopy.shoola.util.concur.tasks.AsyncProcessor$Runner.run(AsyncProcessor.java:91)
	at java.lang.Thread.run(Thread.java:655)
Caused by: omero.ValidationException
    serverStackTrace = "ome.conditions.ValidationException: No row with the given identifier exists: [ome.model.roi.Roi#25]; nested exception is org.hibernate.ObjectNotFoundException: No row with the given identifier exists: [ome.model.roi.Roi#25]
                        	at org.springframework.orm.hibernate3.SessionFactoryUtils.convertHibernateAccessException(SessionFactoryUtils.java:663)
                        	at org.springframework.orm.hibernate3.HibernateAccessor.convertHibernateAccessException(HibernateAccessor.java:412)
                        	at org.springframework.orm.hibernate3.HibernateInterceptor.invoke(HibernateInterceptor.java:117)
                        	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
                        	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:108)
                        	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
                        	at ome.tools.hibernate.ProxyCleanupFilter$Interceptor.invoke(ProxyCleanupFilter.java:231)
                        	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
                        	at ome.services.util.ServiceHandler.invoke(ServiceHandler.java:111)
                        	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
                        	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
                        	at $Proxy75.deleteObject(Unknown Source)

or (rare)

	at org.openmicroscopy.shoola.env.data.OMEROGateway.handleException(OMEROGateway.java:873)
	at org.openmicroscopy.shoola.env.data.OMEROGateway.saveROI(OMEROGateway.java:6605)
	at org.openmicroscopy.shoola.env.data.OmeroImageServiceImpl.saveROI(OmeroImageServiceImpl.java:1338)
	at org.openmicroscopy.shoola.env.data.views.calls.ROISaver$1.doCall(ROISaver.java:74)
	at org.openmicroscopy.shoola.env.data.views.BatchCall.doStep(BatchCall.java:144)
	at org.openmicroscopy.shoola.util.concur.tasks.CompositeTask.doStep(CompositeTask.java:226)
	at org.openmicroscopy.shoola.env.data.views.CompositeBatchCall.doStep(CompositeBatchCall.java:126)
	at org.openmicroscopy.shoola.util.concur.tasks.ExecCommand.exec(ExecCommand.java:165)
	at org.openmicroscopy.shoola.util.concur.tasks.ExecCommand.run(ExecCommand.java:274)
	at org.openmicroscopy.shoola.util.concur.tasks.AsyncProcessor$Runner.run(AsyncProcessor.java:91)
	at java.lang.Thread.run(Thread.java:655)
Caused by: omero.OptimisticLockException
    serverStackTrace = "ome.conditions.OptimisticLockException: Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1; nested exception is org.hibernate.StaleStateException: Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1
                        	at org.springframework.orm.hibernate3.SessionFactoryUtils.convertHibernateAccessException(SessionFactoryUtils.java:675)
                        	at org.springframework.orm.hibernate3.HibernateAccessor.convertHibernateAccessException(HibernateAccessor.java:412)
                        	at org.springframework.orm.hibernate3.HibernateInterceptor.invoke(HibernateInterceptor.java:117)
                        	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
                        	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:108)
                        	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
                        	at ome.tools.hibernate.ProxyCleanupFilter$Interceptor.invoke(ProxyCleanupFilter.java:231)
                        	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
                        	at ome.services.util.ServiceHandler.invoke(ServiceHandler.java:111)
                        	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
                        	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
                        	at $Proxy75.deleteObject(Unknown Source)
                        	at sun.reflect.GeneratedMethodAccessor1783.invoke(Unknown Source)
                        	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
                        	at java.lang.reflect.Method.invoke(Method.java:592)

comment:9 Changed 13 years ago by atarkowska

  • Owner atarkowska deleted

comment:10 Changed 13 years ago by jmoore

  • Owner set to jmoore

comment:11 Changed 13 years ago by jmoore

From Chris, this may be an issue that too many deletes were submitted at once.

Changed 13 years ago by jburel

comment:12 Changed 13 years ago by jburel

Reproduced the problem by

  • select a collection of datasets
  • Delete datasets and contents

comment:13 Changed 13 years ago by jburel <j.burel@…>

(In [56c2bdf8db84a91c8e9f04e8960e600aa2501e56/ome.git] on branch develop) Review code leading to a possible exception Ice::ObjectNotExistException? (see #5749)

comment:14 Changed 13 years ago by jburel

  • Milestone changed from OMERO-Beta4.3 to OMERO-Beta4.3.1
  • Sprint changed from 2011-06-16 (14) to 2011-06-30 (1)

Moved from sprint 2011-06-16 (14)

comment:15 Changed 13 years ago by jmoore

  • Remaining Time set to 1

comment:16 Changed 13 years ago by jmoore

  • Milestone changed from OMERO-Beta4.3.1 to OMERO-Beta4.3.2
  • Sprint 2011-07-07 (1) deleted

Pushing since changes that would possibly fix this aren't really appropriate for 4.3.1 unless it becomes a major issue.

comment:17 Changed 13 years ago by jburel

  • Milestone changed from OMERO-Beta4.3.2 to OME-5.0

comment:18 Changed 12 years ago by jmoore

  • Sprint set to 2012-01-17 (6)
  • Status changed from new to accepted

comment:19 Changed 12 years ago by jmoore

Created a separate ticket for Jean-Marie's issue under #7751.

comment:20 Changed 12 years ago by jmoore

Just reproduced but only in the midst of several other web refresh issues. I've detailed all of those under #7752. My opinion at the moment is that somewhere a handle is being held on to, but I don't have any clues as to where or why.

comment:21 Changed 12 years ago by jmoore

A just happened again: could it be related to the delayed call by the activities window of deleteHandle.errors() ? Once deleteHandle.close() is called, you won't be able to access the handle anymore.

comment:22 Changed 12 years ago by jmoore

  • Cc atarkowska added
  • Remaining Time changed from 1 to 0
  • Resolution set to duplicate
  • Status changed from accepted to closed

Closing in favor of #7752 where I've collected as much information as I can about this issue, including previous duplicate tickets.

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.73911 sec.)

© 2000-2014 University of Dundee & Open Microscopy Environment. Creative Commons Attribution 3.0 Unported License
OME source code is available under the GNU General public license or through commercial license from Glencoe Software

We're Hiring!