[jbossseam-issues] [JBoss JIRA] Created: (JBSEAM-4013) Synchronous invocation of asynchronous method from asynchronously executing method.

[Anton Lyakishev (JIRA)]

Synchronous invocation of asynchronous method from asynchronously executing method.
-----------------------------------------------------------------------------------

                 Key: JBSEAM-4013
                 URL: https://jira.jboss.org/jira/browse/JBSEAM-4013
             Project: Seam
          Issue Type: Bug
          Components: Async
    Affects Versions: 2.1.1.GA
         Environment: Seam 2.1.1GA, JBoss 4.2.3GA.
            Reporter: Anton Lyakishev


There is a problem with REENTRANT flag in AsynchronousInterceptor.java that leads to synchronous invocation of asynchronous method from asynchronously executing method. Any call to a synchronous method will reset the flag, so subsequent calls to asynchronous methods are executed synchronously.

How to reproduce: just add these three classes to quartz example:

Async.java:
________________________
package org.jboss.seam.example.quartz;

import org.jboss.seam.annotations.In;
import org.jboss.seam.annotations.Name;
import org.jboss.seam.annotations.Observer;

@Name( "async" )
public class Async {

    @In( create = true )
    private Async1 async1;

    @Observer( "org.jboss.seam.postInitialization" )
    public void initialize() {
        async1.test( 5000L );
    }

}

Async1.java
________________________
package org.jboss.seam.example.quartz;

import org.jboss.seam.annotations.In;
import org.jboss.seam.annotations.Logger;
import org.jboss.seam.annotations.Name;
import org.jboss.seam.annotations.async.Asynchronous;
import org.jboss.seam.annotations.async.Duration;
import org.jboss.seam.async.AbstractDispatcher;
import org.jboss.seam.async.QuartzTriggerHandle;
import org.jboss.seam.contexts.Contexts;
import org.jboss.seam.log.Log;

@Name( "async1" )
public class Async1 {

    @Logger
    private Log log;
    @In( create = true )
    private Async2 async2;
    private static final String REENTRANT = "org.jboss.seam.async.AsynchronousIntercepter.REENTRANT";

    @Asynchronous
    public QuartzTriggerHandle test( @Duration Long duration ) {
        log.info( "EXECUTING_ASYNCHRONOUS_CALL = #0", Contexts.getEventContext().isSet( AbstractDispatcher.EXECUTING_ASYNCHRONOUS_CALL ) );
        log.info( "1. REENTRANT = #0", Contexts.getEventContext().isSet( REENTRANT ) );
        async2.test( 5000L, "test1" );
        log.info( "2. REENTRANT = #0", Contexts.getEventContext().isSet( REENTRANT ) );
        async2.log( "sync" );
        log.info( "3. REENTRANT = #0", Contexts.getEventContext().isSet( REENTRANT ) );
        async2.test( 10000L, "test2" );
        try {
            Thread.sleep( 15000L );
        } catch( InterruptedException e ) {
        }
        log.info( "4. REENTRANT = #0", Contexts.getEventContext().isSet( REENTRANT ) );
        return null;
    }

}

Async2.java
________________________
package org.jboss.seam.example.quartz;

import org.jboss.seam.annotations.Logger;
import org.jboss.seam.annotations.Name;
import org.jboss.seam.annotations.async.Asynchronous;
import org.jboss.seam.annotations.async.Duration;
import org.jboss.seam.async.AbstractDispatcher;
import org.jboss.seam.async.QuartzTriggerHandle;
import org.jboss.seam.contexts.Contexts;
import org.jboss.seam.log.Log;

@Name( "async2" )
public class Async2 {

    @Logger
    private Log log;

    @Asynchronous
    public QuartzTriggerHandle test( @Duration Long duration, String message ) {
        log( message );
        return null;
    }

    // non-asynchronous method
    public void log( String message ) {
        log.info( "#0: EXECUTING_ASYNCHRONOUS_CALL = #1", message, Contexts.getEventContext().isSet( AbstractDispatcher.EXECUTING_ASYNCHRONOUS_CALL ) );
        log.info( "#0: REENTRANT = #1", message, Contexts.getEventContext().isSet( "org.jboss.seam.async.AsynchronousIntercepter.REENTRANT" ) );
    }

}

Async schedules invocation of Async1. Then Async1 schedules two invocations of Async2. It also calls non-asynchronous method of Async2 before scheduling the second invocation. This causes the REENTRANT flag to be off and the second invocation to be executed synchronously by the same thread. Here is a relevant log:

18:24:34,349 INFO  (main) [ServletContextListener] Welcome to Seam 2.1.1.GA
18:24:37,077 INFO  (main) [QuartzScheduler] Quartz Scheduler v.1.6.0 created.
18:24:37,079 INFO  (main) [RAMJobStore] RAMJobStore initialized.
18:24:37,365 INFO  (main) [Server] JBoss (MX MicroKernel) [4.2.3.GA (build: SVNTag=JBoss_4_2_3_GA date=200807181417)] Started in 22s:600ms
18:24:42,172 INFO  (Sched1_Worker-1) [Async1] EXECUTING_ASYNCHRONOUS_CALL = true
18:24:42,173 INFO  (Sched1_Worker-1) [Async1] 1. REENTRANT = true
18:24:42,175 INFO  (Sched1_Worker-1) [Async1] 2. REENTRANT = true
18:24:42,176 INFO  (Sched1_Worker-1) [Async2] sync: EXECUTING_ASYNCHRONOUS_CALL = true
18:24:42,177 INFO  (Sched1_Worker-1) [Async2] sync: REENTRANT = true
18:24:42,177 INFO  (Sched1_Worker-1) [Async1] 3. REENTRANT = false
18:24:42,185 INFO  (Sched1_Worker-1) [Async2] test2: EXECUTING_ASYNCHRONOUS_CALL = true
18:24:42,185 INFO  (Sched1_Worker-1) [Async2] test2: REENTRANT = true
18:24:47,190 INFO  (Sched1_Worker-2) [Async2] test1: EXECUTING_ASYNCHRONOUS_CALL = true
18:24:47,190 INFO  (Sched1_Worker-2) [Async2] test1: REENTRANT = true
18:24:57,186 INFO  (Sched1_Worker-1) [Async1] 4. REENTRANT = false

Expected behavior: test2 should be invoked asynchronously (by different thread) after the test1.

Changes might be as simple as the following (AsynchronousInterceptor.java):
         boolean flag_is_set = false;
         if (isExecutingAsynchronousCall() && !Contexts.getEventContext().isSet(REENTRANT))
         {
            Contexts.getEventContext().set(REENTRANT, true);
            flag_is_set = true;
         }
         try
         {
             return invocation.proceed();
         }
         finally
         {
             if (flag_is_set)
             {
                 Contexts.getEventContext().remove(REENTRANT);
             }
         }
to make sure we do not reset the REENTRANT flag if it was not set by us.

-- 
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators: https://jira.jboss.org/jira/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira