GroupManager.findGroupsByUser called twice

[heymjo]

Hi,

For this simple task query

List<Task> tasks = processEngine.getTaskService().createTaskQuery().taskCandidateUser("myuser").list;
‍‍‍

I am seeing that the groupmanager.findGroupsByUser is called twice. Is this intended behaviour ? I tried debugging it but it seems to happen somewhere during execution in the ibatis engine and that's hard to debug. Not sure if this helps but i took a thread dump each time from a breakpoint set in the groupmanager.findGroupsByUser. BaseExecutor.createCacheKey seems to be the entry point for the dual execution, if you diff below dumps it should be more visible.

first pass

"main@1" prio=5 tid=0x1 nid=NA runnable
  java.lang.Thread.State: RUNNABLE
     at my.GroupManager.findGroupsByUser(GroupManager.java:65)
     at org.activiti.engine.impl.TaskQueryImpl.getGroupsForCandidateUser(TaskQueryImpl.java:307)
     at org.activiti.engine.impl.TaskQueryImpl.getCandidateGroups(TaskQueryImpl.java:299)
     at sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-1)
     at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
     at java.lang.reflect.Method.invoke(Method.java:597)
     at org.apache.ibatis.reflection.invoker.MethodInvoker.invoke(MethodInvoker.java:22)
     at org.apache.ibatis.reflection.wrapper.BeanWrapper.getBeanProperty(BeanWrapper.java:136)
     at org.apache.ibatis.reflection.wrapper.BeanWrapper.get(BeanWrapper.java:27)
     at org.apache.ibatis.reflection.MetaObject.getValue(MetaObject.java:103)
     at org.apache.ibatis.builder.xml.dynamic.DynamicContext$ContextMap.get(DynamicContext.java:72)
     at org.apache.ibatis.builder.xml.dynamic.DynamicContext$ContextAccessor.getProperty(DynamicContext.java:90)
     at org.apache.ibatis.ognl.OgnlRuntime.getProperty(OgnlRuntime.java:1657)
     at org.apache.ibatis.ognl.ASTProperty.getValueBody(ASTProperty.java:92)
     at org.apache.ibatis.ognl.SimpleNode.evaluateGetValueBody(SimpleNode.java:170)
     at org.apache.ibatis.ognl.SimpleNode.getValue(SimpleNode.java:210)
     at org.apache.ibatis.ognl.ASTNotEq.getValueBody(ASTNotEq.java:49)
     at org.apache.ibatis.ognl.SimpleNode.evaluateGetValueBody(SimpleNode.java:170)
     at org.apache.ibatis.ognl.SimpleNode.getValue(SimpleNode.java:210)
     at org.apache.ibatis.ognl.ASTAnd.getValueBody(ASTAnd.java:56)
     at org.apache.ibatis.ognl.SimpleNode.evaluateGetValueBody(SimpleNode.java:170)
     at org.apache.ibatis.ognl.SimpleNode.getValue(SimpleNode.java:210)
     at org.apache.ibatis.ognl.Ognl.getValue(Ognl.java:333)
     at org.apache.ibatis.ognl.Ognl.getValue(Ognl.java:413)
     at org.apache.ibatis.ognl.Ognl.getValue(Ognl.java:454)
     at org.apache.ibatis.ognl.Ognl.getValue(Ognl.java:433)
     at org.apache.ibatis.builder.xml.dynamic.ExpressionEvaluator.evaluateBoolean(ExpressionEvaluator.java:18)
     at org.apache.ibatis.builder.xml.dynamic.IfSqlNode.apply(IfSqlNode.java:15)
     at org.apache.ibatis.builder.xml.dynamic.MixedSqlNode.apply(MixedSqlNode.java:14)
     at org.apache.ibatis.builder.xml.dynamic.IfSqlNode.apply(IfSqlNode.java:16)
     at org.apache.ibatis.builder.xml.dynamic.MixedSqlNode.apply(MixedSqlNode.java:14)
     at org.apache.ibatis.builder.xml.dynamic.TrimSqlNode.apply(TrimSqlNode.java:27)
     at org.apache.ibatis.builder.xml.dynamic.MixedSqlNode.apply(MixedSqlNode.java:14)
     at org.apache.ibatis.builder.xml.dynamic.MixedSqlNode.apply(MixedSqlNode.java:14)
          at org.apache.ibatis.builder.xml.dynamic.DynamicSqlSource.getBoundSql(DynamicSqlSource.java:22)
     at org.apache.ibatis.mapping.MappedStatement.getBoundSql(MappedStatement.java:198)

     at org.apache.ibatis.executor.BaseExecutor.createCacheKey(BaseExecutor.java:142)

     at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:112)
     at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:72)
     at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:79)
     at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:73)
     at org.activiti.engine.impl.db.DbSqlSession.selectList(DbSqlSession.java:193)
     at org.activiti.engine.impl.persistence.entity.TaskManager.findTasksByQueryCriteria(TaskManager.java:91)
     at org.activiti.engine.impl.TaskQueryImpl.executeList(TaskQueryImpl.java:368)
     at org.activiti.engine.impl.AbstractQuery.execute(AbstractQuery.java:138)
     at org.activiti.engine.impl.interceptor.CommandExecutorImpl.execute(CommandExecutorImpl.java:24)
     at org.activiti.engine.impl.interceptor.CommandContextInterceptor.execute(CommandContextInterceptor.java:42)
     at org.activiti.spring.SpringTransactionInterceptor$1.doInTransaction(SpringTransactionInterceptor.java:42)
     at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:130)
     at org.activiti.spring.SpringTransactionInterceptor.execute(SpringTransactionInterceptor.java:40)
     at org.activiti.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:33)
     at org.activiti.engine.impl.AbstractQuery.list(AbstractQuery.java:112)
     at my.ProcessVarSecurityTest.testCompleteAndRoleRemoved(ProcessVarSecurityTest.java:111)
     at sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-1)
     at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
     at java.lang.reflect.Method.invoke(Method.java:597)
     at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:80)
     at org.testng.internal.MethodInvocationHelper$1.runTestMethod(MethodInvocationHelper.java:182)
     at org.springframework.test.context.testng.AbstractTestNGSpringContextTests.run(AbstractTestNGSpringContextTests.java:158)
     at sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-1)
     at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
     at java.lang.reflect.Method.invoke(Method.java:597)
     at org.testng.internal.MethodInvocationHelper.invokeHookable(MethodInvocationHelper.java:194)
     at org.testng.internal.Invoker.invokeMethod(Invoker.java:694)
     at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:893)
     at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1218)
     at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:127)
     at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:111)
     at org.testng.TestRunner.privateRun(TestRunner.java:758)
     at org.testng.TestRunner.run(TestRunner.java:613)
     at org.testng.SuiteRunner.runTest(SuiteRunner.java:334)
     at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:329)
     at org.testng.SuiteRunner.privateRun(SuiteRunner.java:291)
     at org.testng.SuiteRunner.run(SuiteRunner.java:240)
     at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:53)
     at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:87)
     at org.testng.TestNG.runSuitesSequentially(TestNG.java:1170)
     at org.testng.TestNG.runSuitesLocally(TestNG.java:1095)
     at org.testng.TestNG.run(TestNG.java:1007)
     at org.testng.remote.RemoteTestNG.run(RemoteTestNG.java:109)
     at org.testng.remote.RemoteTestNG.initAndRun(RemoteTestNG.java:202)
     at org.testng.remote.RemoteTestNG.main(RemoteTestNG.java:173)
     at org.testng.RemoteTestNGStarter.main(RemoteTestNGStarter.java:111)

‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

second pass

"main@1" prio=5 tid=0x1 nid=NA runnable
  java.lang.Thread.State: RUNNABLE
     at my.GroupManager.findGroupsByUser(GroupManager.java:65)
     at org.activiti.engine.impl.TaskQueryImpl.getGroupsForCandidateUser(TaskQueryImpl.java:307)
     at org.activiti.engine.impl.TaskQueryImpl.getCandidateGroups(TaskQueryImpl.java:299)
     at sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-1)
     at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
     at java.lang.reflect.Method.invoke(Method.java:597)
     at org.apache.ibatis.reflection.invoker.MethodInvoker.invoke(MethodInvoker.java:22)
     at org.apache.ibatis.reflection.wrapper.BeanWrapper.getBeanProperty(BeanWrapper.java:136)
     at org.apache.ibatis.reflection.wrapper.BeanWrapper.get(BeanWrapper.java:27)
     at org.apache.ibatis.reflection.MetaObject.getValue(MetaObject.java:103)
     at org.apache.ibatis.builder.xml.dynamic.DynamicContext$ContextMap.get(DynamicContext.java:72)
     at org.apache.ibatis.builder.xml.dynamic.DynamicContext$ContextAccessor.getProperty(DynamicContext.java:90)
     at org.apache.ibatis.ognl.OgnlRuntime.getProperty(OgnlRuntime.java:1657)
     at org.apache.ibatis.ognl.ASTProperty.getValueBody(ASTProperty.java:92)
     at org.apache.ibatis.ognl.SimpleNode.evaluateGetValueBody(SimpleNode.java:170)
     at org.apache.ibatis.ognl.SimpleNode.getValue(SimpleNode.java:210)
     at org.apache.ibatis.ognl.ASTNotEq.getValueBody(ASTNotEq.java:49)
     at org.apache.ibatis.ognl.SimpleNode.evaluateGetValueBody(SimpleNode.java:170)
     at org.apache.ibatis.ognl.SimpleNode.getValue(SimpleNode.java:210)
     at org.apache.ibatis.ognl.ASTAnd.getValueBody(ASTAnd.java:56)
     at org.apache.ibatis.ognl.SimpleNode.evaluateGetValueBody(SimpleNode.java:170)
     at org.apache.ibatis.ognl.SimpleNode.getValue(SimpleNode.java:210)
     at org.apache.ibatis.ognl.Ognl.getValue(Ognl.java:333)
     at org.apache.ibatis.ognl.Ognl.getValue(Ognl.java:413)
     at org.apache.ibatis.ognl.Ognl.getValue(Ognl.java:454)
     at org.apache.ibatis.ognl.Ognl.getValue(Ognl.java:433)
     at org.apache.ibatis.builder.xml.dynamic.ExpressionEvaluator.evaluateBoolean(ExpressionEvaluator.java:18)
     at org.apache.ibatis.builder.xml.dynamic.IfSqlNode.apply(IfSqlNode.java:15)
     at org.apache.ibatis.builder.xml.dynamic.MixedSqlNode.apply(MixedSqlNode.java:14)
     at org.apache.ibatis.builder.xml.dynamic.IfSqlNode.apply(IfSqlNode.java:16)
     at org.apache.ibatis.builder.xml.dynamic.MixedSqlNode.apply(MixedSqlNode.java:14)
     at org.apache.ibatis.builder.xml.dynamic.TrimSqlNode.apply(TrimSqlNode.java:27)
     at org.apache.ibatis.builder.xml.dynamic.MixedSqlNode.apply(MixedSqlNode.java:14)
     at org.apache.ibatis.builder.xml.dynamic.MixedSqlNode.apply(MixedSqlNode.java:14)
     at org.apache.ibatis.builder.xml.dynamic.DynamicSqlSource.getBoundSql(DynamicSqlSource.java:22)
     at org.apache.ibatis.mapping.MappedStatement.getBoundSql(MappedStatement.java:198)
     at org.apache.ibatis.executor.statement.BaseStatementHandler.<init>(BaseStatementHandler.java:45)
     at org.apache.ibatis.executor.statement.PreparedStatementHandler.<init>(PreparedStatementHandler.java:16)
     at org.apache.ibatis.executor.statement.RoutingStatementHandler.<init>(RoutingStatementHandler.java:27)
     at org.apache.ibatis.session.Configuration.newStatementHandler(Configuration.java:282)
     at org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:39)
     at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:243)
     at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:117)
     at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:72)[/color]
     at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:79)
     at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:73)
     at org.activiti.engine.impl.db.DbSqlSession.selectList(DbSqlSession.java:193)
     at org.activiti.engine.impl.persistence.entity.TaskManager.findTasksByQueryCriteria(TaskManager.java:91)
     at org.activiti.engine.impl.TaskQueryImpl.executeList(TaskQueryImpl.java:368)
     at org.activiti.engine.impl.AbstractQuery.execute(AbstractQuery.java:138)
     at org.activiti.engine.impl.interceptor.CommandExecutorImpl.execute(CommandExecutorImpl.java:24)
     at org.activiti.engine.impl.interceptor.CommandContextInterceptor.execute(CommandContextInterceptor.java:42)
     at org.activiti.spring.SpringTransactionInterceptor$1.doInTransaction(SpringTransactionInterceptor.java:42)
     at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:130)
     at org.activiti.spring.SpringTransactionInterceptor.execute(SpringTransactionInterceptor.java:40)
     at org.activiti.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:33)
     at org.activiti.engine.impl.AbstractQuery.list(AbstractQuery.java:112)
     at my.ProcessVarSecurityTest.testCompleteAndRoleRemoved(ProcessVarSecurityTest.java:111)
     at sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-1)
     at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
     at java.lang.reflect.Method.invoke(Method.java:597)
     at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:80)
     at org.testng.internal.MethodInvocationHelper$1.runTestMethod(MethodInvocationHelper.java:182)
     at org.springframework.test.context.testng.AbstractTestNGSpringContextTests.run(AbstractTestNGSpringContextTests.java:158)
     at sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-1)
     at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
     at java.lang.reflect.Method.invoke(Method.java:597)
     at org.testng.internal.MethodInvocationHelper.invokeHookable(MethodInvocationHelper.java:194)
     at org.testng.internal.Invoker.invokeMethod(Invoker.java:694)
     at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:893)
     at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1218)
     at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:127)
     at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:111)
     at org.testng.TestRunner.privateRun(TestRunner.java:758)
     at org.testng.TestRunner.run(TestRunner.java:613)
     at org.testng.SuiteRunner.runTest(SuiteRunner.java:334)
     at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:329)
     at org.testng.SuiteRunner.privateRun(SuiteRunner.java:291)
     at org.testng.SuiteRunner.run(SuiteRunner.java:240)
     at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:53)
     at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:87)
     at org.testng.TestNG.runSuitesSequentially(TestNG.java:1170)
     at org.testng.TestNG.runSuitesLocally(TestNG.java:1095)
     at org.testng.TestNG.run(TestNG.java:1007)
     at org.testng.remote.RemoteTestNG.run(RemoteTestNG.java:109)
     at org.testng.remote.RemoteTestNG.initAndRun(RemoteTestNG.java:202)
     at org.testng.remote.RemoteTestNG.main(RemoteTestNG.java:173)
     at org.testng.RemoteTestNGStarter.main(RemoteTestNGStarter.java:111)

‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

[trademak]

Hi,

You are right that it's called twice. It's caused by the iBatis SQL query selectTaskByQueryCriteriaSql.
I couldn't see immediately how we can prevent it be being called twice, but it may be a good idea to create a JIRA for this.

Thanks,

[heymjo]

thanks for confirming, created http://jira.codehaus.org/browse/ACT-1206

I tested on 5.8 and 5.9, both show the same behaviour.