Bug: re exceptions possibly lead to logout

[jamoore]

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.

[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?

[jmoore <josh@…>]

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

[wmoore]

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

[jmoore]

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

[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

[wmoore]

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?

[jmoore]

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)))

[jmoore]

Moving to 4.3.1 for handling

[wmoore]

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

[Will Moore <will@…>]

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

[Chris Allan <callan@…>]

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

[wmoore]

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

[cxallan]

Moved from sprint 2011-07-21 (1)

[Will Moore <will@…>]

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

[cxallan]

Closing in favour of more in depth #6365.