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 #5835 (closed)

Opened 13 years ago

Closed 13 years ago

Bug: re exceptions possibly lead to logout

Reported by: jamoore Owned by: wmoore
Priority: major Milestone: OMERO-Beta4.3.2
Component: General Version: n.a.
Keywords: n.a. Cc: python-team@…
Resources: n.a. Referenced By: jmoore
References: n.a. Remaining Time: n.a.
Sprint: 2011-08-04 (2)

Description

I know this is probably a duplicate of several other tickets, but I have a particularly good log snapshot that hopefully will solve at least another instance of this.

See stack trace and screen shot below.

NB: It'd be nice if we could 1) get the stack trace from outside the call to inner from safeWrap printed and 2) if we could get the prx names printed.

Attachments (2)

re.txt (19.0 KB) - added by jmoore 13 years ago.
web-logged-out-maybe.png (58.7 KB) - added by jmoore 13 years ago.

Download all attachments as: .zip

Change History (22)

comment:1 Changed 13 years ago by jmoore

Changed 13 years ago by jmoore

Changed 13 years ago by jmoore

comment:2 Changed 13 years ago by jmoore

I'm going to fix the references to MissingPyramidException, but we need some discussion of:

            except Ice.Exception, x:
                # Still Failed
                logger.debug("Ice.Exception (2) on safe call %s(%s,%s)" % (attr, str(args), str(kwargs)))
                logger.debug(traceback.format_exc())
                try:
#                    if self._conn.c.sf.getSessionService().getReferenceCount(self._conn._sessionUuid) > 0:
                    # Recreate connection
                    self._connect(forcejoin=True)
                    logger.debug('last try for %s' % attr)
                    # Last try, don't catch exception
                    func = getattr(self._obj, attr)
                    return func(*args, **kwargs)

I'm not sure retrying makes sense, especially on the stateful services. Thoughts?

comment:3 Changed 13 years ago by jmoore <josh@…>

(In [80adc30ff044cb58ec7ccf95628d4ac409a122b8/ome.git] on branch develop) Change MissingPyramidException to ConcurrencyException throughout Omero{Web,Py} (See #5835)

comment:4 Changed 13 years ago by wmoore

(In [d894b524b4b2baa4e894cc195d597c16ea059f0f/ome.git] on branch develop) Printing stack traces to debug log in Blitz safeCallWrap. See #5835

comment:5 Changed 13 years ago by jmoore

  • Owner changed from jmoore to wmoore

Passing off to Will for his thoughts after his new logging.

comment:6 Changed 13 years ago by wmoore

Not sure how to recreate the logout when exception is thrown.

Quick test of throwing an exception within safeCallWrap - Added this into the ProxyObjectWrapper? to throw a mock exception on renderingEngine.load()

    def __getattr__ (self, attr):
        """
        Returns named attribute of the wrapped service. 
        If attribute is a method, the method is wrapped to handle exceptions, connection etc.
        
        @param attr:    Attribute name
        @type attr:     String
        @return:        Attribute or wrapped method
        """
        # safe call wrapper
        obj = self._obj or self._getObj()
        rv = getattr(obj, attr)
        if callable(rv):
            if attr == 'load':
                rv = self.testThrow
            rv = safeCallWrap(self, attr, rv)
        #self._conn.updateTimeout()
        return rv
        
    def testThrow(self):
        e = omero.ConcurrencyException("MOCK MissingPyramidException")
        e.backOff = (3 * 60 * 60 * 1000) + (20 * 60 * 1000) + (45 * 1000) # 3 hours
        raise e

And got this log when exception is thrown, but no log-out

Thu, 09 Jun 2011 12:10:47 webgateway   DEBUG    trying stored connection with userAgent: OMERO.web  ckey: S:5dee46f0-b2d6-4e72-921e-24b5c0f49d41#1
Thu, 09 Jun 2011 12:10:47 webgateway   DEBUG    [('S:5dee46f0-b2d6-4e72-921e-24b5c0f49d41#1', <webclient.webclient_gateway.OmeroWebGateway object at 0x288e890>)]
Thu, 09 Jun 2011 12:10:47 views-web    DEBUG    TEMPLATE: webclient/data/container_subtree.html
Thu, 09 Jun 2011 12:10:50 webgateway   DEBUG    :: (session) root localhost 4064
Thu, 09 Jun 2011 12:10:50 webgateway   DEBUG    :: (request) None None None
Thu, 09 Jun 2011 12:10:50 webgateway   DEBUG    trying stored connection with userAgent: OMERO.web  ckey: S:5dee46f0-b2d6-4e72-921e-24b5c0f49d41#1
Thu, 09 Jun 2011 12:10:50 webgateway   DEBUG    [('S:5dee46f0-b2d6-4e72-921e-24b5c0f49d41#1', <webclient.webclient_gateway.OmeroWebGateway object at 0x288e890>)]
Thu, 09 Jun 2011 12:10:50 views-web    DEBUG    TEMPLATE: webclient/annotations/metadata_general.html
Thu, 09 Jun 2011 12:10:51 blitz_gateway DEBUG    omero.ConcurrencyException on safeCallWrap load((),{})
Thu, 09 Jun 2011 12:10:51 blitz_gateway DEBUG    Traceback (most recent call last):
  File "/Users/will/Desktop/OMERO/dist/lib/python/omero/gateway/__init__.py", line 2885, in inner
    return f(*args, **kwargs)
  File "/Users/will/Desktop/OMERO/dist/lib/python/omero/gateway/__init__.py", line 3199, in testThrow
    raise e
ConcurrencyException: exception ::omero::ConcurrencyException
{
    serverStackTrace = MOCK MissingPyramidException
    serverExceptionClass = 
    message = 
    backOff = 12045000
}

Thu, 09 Jun 2011 12:10:51 blitz_gateway DEBUG    ConcurrencyException, bailing out
Thu, 09 Jun 2011 12:10:51 blitz_gateway DEBUG    omero.ConcurrencyException on safeCallWrap load((),{})
Thu, 09 Jun 2011 12:10:51 blitz_gateway DEBUG    Traceback (most recent call last):
  File "/Users/will/Desktop/OMERO/dist/lib/python/omero/gateway/__init__.py", line 2885, in inner
    return f(*args, **kwargs)
  File "/Users/will/Desktop/OMERO/dist/lib/python/omero/gateway/__init__.py", line 3199, in testThrow
    raise e
ConcurrencyException: exception ::omero::ConcurrencyException
{
    serverStackTrace = MOCK MissingPyramidException
    serverExceptionClass = 
    message = 
    backOff = 12045000
}

Thu, 09 Jun 2011 12:10:51 blitz_gateway DEBUG    ConcurrencyException, bailing out
Thu, 09 Jun 2011 12:10:51 webgateway   DEBUG    :: (session) root localhost 4064
Thu, 09 Jun 2011 12:10:51 webgateway   DEBUG    :: (request) None None None
Thu, 09 Jun 2011 12:10:51 webgateway   DEBUG    trying stored connection with userAgent: OMERO.web  ckey: S:5dee46f0-b2d6-4e72-921e-24b5c0f49d41#1
Thu, 09 Jun 2011 12:10:51 webgateway   DEBUG    [('S:5dee46f0-b2d6-4e72-921e-24b5c0f49d41#1', <webclient.webclient_gateway.OmeroWebGateway object at 0x288e890>)]
Thu, 09 Jun 2011 12:10:51 views-web    DEBUG    TEMPLATE: webclient/data/containers_icon.html
Thu, 09 Jun 2011 12:10:51 webgateway   DEBUG    :: (session) root localhost 4064
Thu, 09 Jun 2011 12:10:51 webgateway   DEBUG    :: (request) None None None
Thu, 09 Jun 2011 12:10:51 webgateway   DEBUG    trying stored connection with userAgent: OMERO.web  ckey: S:5dee46f0-b2d6-4e72-921e-24b5c0f49d41#1
Thu, 09 Jun 2011 12:10:51 webgateway   DEBUG    [('S:5dee46f0-b2d6-4e72-921e-24b5c0f49d41#1', <webclient.webclient_gateway.OmeroWebGateway object at 0x288e890>)]
Thu, 09 Jun 2011 12:20:36 webgateway   DEBUG    :: (session) root localhost 4064

comment:7 Changed 13 years ago by wmoore

  • Resolution set to fixed
  • Status changed from new to closed

Sorry - can't see an easy way to log the prx names when safeCallWrap throws an exception - without making changes that risk adding bugs at this late stage.
Closing, since we have enough logging info (method names) for now?

comment:8 Changed 13 years ago by jmoore

  • Priority changed from blocker to major
  • Resolution fixed deleted
  • Status changed from closed to reopened

Lowering priority for review after release. With the following patch I had output like this:

In [9]: q.findAllByQuery("select x", None)
DEBUG:blitz_gateway:QueryException on safeCallWrap to <8b6c800a-dc27-4c79-9721-5d2479dc62bfomero.api.IQuery> findAllByQuery(('select x', None),{})
DEBUG:blitz_gateway:Traceback (most recent call last):
  File "/Users/moore/git/components/tools/OmeroPy/build/lib/omero/gateway/__init__.py", line 2894, in inner
    return f(*args, **kwargs)
  File "/Users/moore/git/components/tools/OmeroPy/build/lib/omero_api_IQuery_ice.py", line 138, in findAllByQuery
    return _M_omero.api.IQuery._op_findAllByQuery.invoke(self, ((query, params), _ctx))
QueryException: exception ::omero::QueryException
{
    serverStackTrace = ome.services.query.QueryException: Illegal query:select x
No data type for node: org.hibernate.hql.ast.tree.IdentNode 

~/git/components/tools/OmeroPy $ git diff .
diff --git a/components/tools/OmeroPy/src/omero/gateway/__init__.py b/components/tools/OmeroPy/src/omero/gateway/__init__.py
index a263651..eb8b646 100644
--- a/components/tools/OmeroPy/src/omero/gateway/__init__.py
+++ b/components/tools/OmeroPy/src/omero/gateway/__init__.py
@@ -2879,34 +2879,27 @@ def safeCallWrap (self, attr, f): #pragma: no cover
     @return:        Wrapped function
     @rtype:         Function
     """
-    
+
+    try:
+        __f__name = f.im_self.ice_getIdentity().name
+    except:
+        __f__name = "unknown"
+
+    def debug(exc_class, args, kwargs):
+        logger.debug( "%s on safeCallWrap to <%s> %s(%s,%s)", exc_class, __f__name, attr, args, kwargs)
+        logger.debug(traceback.format_exc())
+
     def inner (*args, **kwargs):
         try:
             return f(*args, **kwargs)
-        except omero.ResourceError:
-            logger.debug( "omero.ResourceError on safeCallWrap %s(%s,%s)" % (attr, str(args), str(kwargs)))
-            logger.debug(traceback.format_exc())
-            raise
-        except omero.SecurityViolation:
-            logger.debug( "omero.SecurityViolation on safeCallWrap %s(%s,%s)" % (attr, str(args), str(kwargs)))
-            logger.debug(traceback.format_exc())
+        except (Ice.MemoryLimitException,\
+                omero.ApiUsageException,\
+    def debug(exc_class, args, kwargs):
+        logger.debug( "%s on safeCallWrap to <%s> %s(%s,%s)", exc_class, __f__name, attr, args, kwargs)
+        logger.debug(traceback.format_exc())
+
     def inner (*args, **kwargs):
         try:
             return f(*args, **kwargs)
-        except omero.ResourceError:
-            logger.debug( "omero.ResourceError on safeCallWrap %s(%s,%s)" % (attr, str(args), str(kwargs)))
-            logger.debug(traceback.format_exc())
-            raise
-        except omero.SecurityViolation:
-            logger.debug( "omero.SecurityViolation on safeCallWrap %s(%s,%s)" % (attr, str(args), str(kwargs)))
-            logger.debug(traceback.format_exc())
+        except (Ice.MemoryLimitException,\
+                omero.ApiUsageException,\
+                omero.InternalException,\
+                omero.ResourceError,\
+                omero.SecurityViolation,\
+                omero.ConcurrencyException), e:
+            debug(e.__class__.__name__, args, kwargs)
             raise
-        except omero.ApiUsageException:
-            logger.debug( "omero.ApiUsageException on safeCallWrap %s(%s,%s)" % (attr, str(args), str(kwargs)))
-            logger.debug(traceback.format_exc())
-            raise
-        except Ice.MemoryLimitException:
-            logger.debug( "omero.MemoryLimitException on safeCallWrap %s(%s,%s)" % (attr, str(args), str(kwargs)))
-            logger.debug(traceback.format_exc())
-            raise
-        except omero.InternalException:
-            logger.debug( "omero.InternalException on safeCallWrap %s(%s,%s)" % (attr, str(args), str(kwargs)))
-            logger.debug(traceback.format_exc())
-            raise
-        except omero.ConcurrencyException:
-            logger.debug( "omero.ConcurrencyException on safeCallWrap %s(%s,%s)" % (attr, str(args), str(kwargs)))
-            logger.debug(traceback.format_exc())
-            raise # ticket:5835
         except Ice.Exception, x:
             # Failed
             logger.debug( "Ice.Exception (1) on safe call %s(%s,%s)" % (attr, str(args), str(kwargs)))

comment:9 Changed 13 years ago by jmoore

  • Milestone changed from OMERO-Beta4.3 to OMERO-Beta4.3.1

Moving to 4.3.1 for handling

comment:10 Changed 13 years ago by wmoore

  • Owner wmoore deleted
  • Status changed from reopened to new

comment:11 Changed 13 years ago by wmoore

  • Owner set to wmoore

comment:12 Changed 13 years ago by wmoore

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

Not going to make big changes to exception handling in 4.3.1, pushing.

comment:13 Changed 13 years ago by wmoore

  • Sprint set to 2011-07-21 (1)

comment:14 Changed 13 years ago by wmoore

  • Status changed from new to accepted

comment:15 Changed 13 years ago by Will Moore <will@…>

(In [5d4254ce58e5a9103cf6c4815a0065bbefb9c7d7/ome.git] on branch develop) Applying safeCallWrap patch. See #5835

comment:16 Changed 13 years ago by Chris Allan <callan@…>

(In [e3aa9f05b575eb440ba0a43ae9a70d82cf28d509/ome.git] on branch develop) Complete safeCallWrap() exception handling rework. (See #5835)

comment:17 Changed 13 years ago by wmoore

Do we want to consider logging failures in safeCallWrap with logger.error instead of logger.debug ?

comment:18 Changed 13 years ago by cxallan

  • Sprint changed from 2011-07-21 (1) to 2011-08-04 (2)

Moved from sprint 2011-07-21 (1)

comment:19 Changed 13 years ago by Will Moore <will@…>

(In [7d1857a32c4eaa580e0b4abdb56020451e008b3c/ome.git] on branch develop) Upgrading logging of exceptions in safeCallWrap to logger.warn(). See #5835

comment:20 Changed 13 years ago by cxallan

  • Resolution set to fixed
  • Status changed from accepted to closed

Closing in favour of more in depth #6365.

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

We're Hiring!