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

[ https://jira.jboss.org/jira/browse/JBSEAM-4013?page=com.atlassian.jira.pl... ] Anton Lyakishev updated JBSEAM-4013: ------------------------------------ Description: 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. Another way to fix is to make sure non-asynchronous methods go short route: @AroundInvoke public Object aroundInvoke(InvocationContext invocation) throws Exception { if (!invocation.getMethod().isAnnotationPresent(Asynchronous.class)) return invocation.proceed(); boolean scheduleAsync = !isExecutingAsynchronousCall() || Contexts.getEventContext().isSet(REENTRANT); ... was: 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