Uploaded image for project: 'Nuxeo Platform'
  1. Nuxeo Platform
  2. NXP-22955

Improve AsyncEventExecutor exceptions handling

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 9.3
    • Component/s: Events / Works, Runtime

      Description

      We want to improve AsyncEventExecutor exception handling in order to not log expected error as ERROR. See the current error below:

      2017-08-21 17:33:39,252 ERROR [Nuxeo-Work-default-2:170133511393893.2079590158] [org.nuxeo.ecm.core.event.impl.AsyncEventExecutor] Failed to execute async event default on listener notificationListener
      org.nuxeo.ecm.core.api.NuxeoException: javax.resource.ResourceException: Interrupted while requesting permit.
      	at org.nuxeo.ecm.core.storage.sql.ra.ConnectionFactoryImpl.getConnection(ConnectionFactoryImpl.java:117)
      	at org.nuxeo.ecm.core.storage.sql.ra.ConnectionFactoryImpl.getSession(ConnectionFactoryImpl.java:166)
      	at org.nuxeo.ecm.core.repository.RepositoryService.getSession(RepositoryService.java:204)
      	at org.nuxeo.ecm.core.api.local.LocalSession.createSession(LocalSession.java:127)
      	at org.nuxeo.ecm.core.api.local.LocalSession.<init>(LocalSession.java:84)
      	at org.nuxeo.ecm.core.api.CoreSessionServiceImpl.createCoreSession(CoreSessionServiceImpl.java:43)
      	at org.nuxeo.ecm.core.api.CoreInstance.openCoreSession(CoreInstance.java:163)
      	at org.nuxeo.ecm.core.api.CoreInstance.openCoreSessionSystem(CoreInstance.java:98)
      	at org.nuxeo.ecm.core.event.impl.ReconnectedEventBundleImpl.getReconnectedCoreSession(ReconnectedEventBundleImpl.java:93)
      	at org.nuxeo.ecm.core.event.impl.ReconnectedEventBundleImpl.getReconnectedEvents(ReconnectedEventBundleImpl.java:111)
      	at org.nuxeo.ecm.core.event.impl.ReconnectedEventBundleImpl.iterator(ReconnectedEventBundleImpl.java:222)
      	at org.nuxeo.ecm.platform.ec.notification.NotificationEventListener.handleEvent(NotificationEventListener.java:108)
      	at org.nuxeo.ecm.core.event.impl.AsyncEventExecutor$ListenerWork.work(AsyncEventExecutor.java:218)
      	at org.nuxeo.ecm.core.work.AbstractWork.runWorkWithTransaction(AbstractWork.java:373)
      	at org.nuxeo.ecm.core.work.AbstractWork.run(AbstractWork.java:332)
      	at org.nuxeo.ecm.core.work.WorkHolder.run(WorkHolder.java:57)
      	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
      	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
      	at java.lang.Thread.run(Thread.java:745)
      Caused by: javax.resource.ResourceException: Interrupted while requesting permit.
      	at org.apache.geronimo.connector.outbound.AbstractSinglePoolConnectionInterceptor.getConnection(AbstractSinglePoolConnectionInterceptor.java:97)
      	at org.nuxeo.runtime.jtajca.NuxeoPool$1.getConnection(NuxeoPool.java:66)
      	at org.apache.geronimo.connector.outbound.ThreadLocalCachingConnectionInterceptor.getConnection(ThreadLocalCachingConnectionInterceptor.java:70)
      	at org.apache.geronimo.connector.outbound.TransactionEnlistingInterceptor.getConnection(TransactionEnlistingInterceptor.java:49)
      	at org.apache.geronimo.connector.outbound.TransactionCachingInterceptor.getConnection(TransactionCachingInterceptor.java:101)
      	at org.apache.geronimo.connector.outbound.ConnectionHandleInterceptor.getConnection(ConnectionHandleInterceptor.java:43)
      	at org.apache.geronimo.connector.outbound.TCCLInterceptor.getConnection(TCCLInterceptor.java:39)
      	at org.apache.geronimo.connector.outbound.ConnectionTrackingInterceptor.getConnection(ConnectionTrackingInterceptor.java:66)
      	at org.apache.geronimo.connector.outbound.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:77)
      	at org.nuxeo.runtime.jtajca.NuxeoContainer$ConnectionManagerWrapper.allocateConnection(NuxeoContainer.java:764)
      	at org.nuxeo.ecm.core.storage.sql.ra.ConnectionFactoryImpl.getConnection(ConnectionFactoryImpl.java:103)
      	... 18 more
      Caused by: java.lang.InterruptedException
      	at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1326)
      	at java.util.concurrent.Semaphore.tryAcquire(Semaphore.java:409)
      	at org.apache.geronimo.connector.outbound.AbstractSinglePoolConnectionInterceptor.getConnection(AbstractSinglePoolConnectionInterceptor.java:78)
      	... 28 more
      

      When we have a look at code logging this error:

              @Override
              public void cleanUp(boolean ok, Exception e) {
                  super.cleanUp(ok, e);
                  bundle.disconnect();
                  if (e != null && !(e instanceof InterruptedException) && !(e instanceof ConcurrentUpdateException)) {
                      log.error("Failed to execute async event " + bundle.getName() + " on listener " + listenerName, e);
                  }
                  if (listener != null) {
                      EventStats stats = Framework.getLocalService(EventStats.class);
                      if (stats != null) {
                          stats.logAsyncExec(listener, System.currentTimeMillis() - getStartTime());
                      }
                      listener = null;
                  }
              }
      

      The method should handle the InterruptedException present in the exception cause.

        Attachments

          Issue Links

            Activity

              People

              • Votes:
                0 Vote for this issue
                Watchers:
                2 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved:

                  Time Tracking

                  Estimated:
                  Original Estimate - Not Specified
                  Not Specified
                  Remaining:
                  Remaining Estimate - 0 minutes
                  0m
                  Logged:
                  Time Spent - 3 hours
                  3h