Intermittent MVEL reflection failures invoking methods on Drools global variable bindings

[Mike Rodriguez]

---- First some background information ----

As a simple example that can represent what I am seeing, say I have the following DRL.

<<<DRL START>>>

package my.drools

global some.org.FnClass fn_1;

global some.org.FnClass fn_2;

rule test_rule

     when

        b : some.org.model.MyClass(true == fn_1.invoke(this))

     then

       fn_2.invoke(drools, b)

end

<<<DRL END>>>

Where some.org.model.MyClass is just a POJO essentially.

The RHS is not where the problem is, but I have it set up similar to this for the rule that is failing.

Let some.org.FnClass looks like:

<<<Class START>>>

package some.org;

public interface FnClass {

  public Object invoke(Object o) { <do some work here and return an instance of java.lang.Boolean> };

}

<<<CLASS END>>>>

The FnClass has a generic Object return type and argument type, but it definitely returns a Boolean in the scenario I describe here.

Now, I create a Drools KieBase off of the above DRL resource.  I then assign the globals fn_1 and fn_2 to anonymous instances of the

FnClass interface.

I make a session and run these rules with a *lot* of data that will evaluate the LHS of the example rule I have above `test_rule`.

---- The problem ----

Sometimes, on rare occasions, when a rule set up just like this is ran, I get an exception from the reflection done deeply within the MvelConditionEvaluator code.

From the stack trace, it looks like this is happening during fact insertion and *prior* to calling KieSession#fireAllRules since I am not seeing any rule activation information involved in the stack trace, and this is all happening in the Alpha network.  I know that this rule LHS can be evaluated during fact insertion since many instances of the some.org.model.MyClass class are directly inserted via KieSession#insert.

The stack trace looks like this:

<<<START STACKTRACE>>>

[Error: null]

[Near : {... true == fn_1657.invoke(this) ....}]

             ^

[Line: 1, Column: 1]

at org.mvel2.optimizers.impl.refl.ReflectiveAccessorOptimizer.compileGetChain(ReflectiveAccessorOptimizer.java:431)

at org.mvel2.optimizers.impl.refl.ReflectiveAccessorOptimizer.optimizeAccessor(ReflectiveAccessorOptimizer.java:140)

at org.mvel2.ast.ASTNode.optimize(ASTNode.java:159)

at org.mvel2.ast.ASTNode.getReducedValueAccelerated(ASTNode.java:115)

at org.mvel2.ast.BinaryOperation.getReducedValueAccelerated(BinaryOperation.java:114)

at org.mvel2.compiler.ExecutableAccessor.getValue(ExecutableAccessor.java:42)

at org.mvel2.MVEL.executeExpression(MVEL.java:930)

at org.drools.core.util.MVELSafeHelper$RawMVELEvaluator.executeExpression(MVELSafeHelper.java:481)

at org.drools.core.rule.constraint.MvelConditionEvaluator.evaluate(MvelConditionEvaluator.java:77)

at org.drools.core.rule.constraint.MvelConditionEvaluator.evaluate(MvelConditionEvaluator.java:62)

at org.drools.core.rule.constraint.MvelConstraint.evaluate(MvelConstraint.java:216)

at org.drools.core.rule.constraint.MvelConstraint.isAllowed(MvelConstraint.java:173)

at org.drools.core.reteoo.AlphaNode.assertObject(AlphaNode.java:134)

at org.drools.core.reteoo.CompositeObjectSinkAdapter.doPropagateAssertObject(CompositeObjectSinkAdapter.java:502)

at org.drools.core.reteoo.CompositeObjectSinkAdapter.propagateAssertObject(CompositeObjectSinkAdapter.java:387)

at org.drools.core.reteoo.ObjectTypeNode.assertObject(ObjectTypeNode.java:288)

at org.drools.core.reteoo.EntryPointNode.assertObject(EntryPointNode.java:251)

at org.drools.core.common.NamedEntryPoint.insert(NamedEntryPoint.java:367)

at org.drools.core.common.NamedEntryPoint.insert(NamedEntryPoint.java:286)

at org.drools.core.impl.StatefulKnowledgeSessionImpl.insert(StatefulKnowledgeSessionImpl.java:1430)

at org.drools.core.impl.StatefulKnowledgeSessionImpl.insert(StatefulKnowledgeSessionImpl.java:1372)

        <Omitted -- Unrelated to Drools from this point on>

        

Caused by: java.lang.IllegalArgumentException

at sun.reflect.GeneratedMethodAccessor15.invoke(Unknown Source)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

at java.lang.reflect.Method.invoke(Method.java:597)

at org.mvel2.optimizers.impl.refl.ReflectiveAccessorOptimizer.getMethod(ReflectiveAccessorOptimizer.java:1097)

at org.mvel2.optimizers.impl.refl.ReflectiveAccessorOptimizer.getMethod(ReflectiveAccessorOptimizer.java:980)

at org.mvel2.optimizers.impl.refl.ReflectiveAccessorOptimizer.compileGetChain(ReflectiveAccessorOptimizer.java:373)

... 38 more

<<<END STACKTRACE>>>

I *know* that this same KieBase is used to create identical KieSession's many times.  Most of these sessions work fine, with facts being inserted evaluating this same rule via the KieSession#insert.

I have reason to believe that the same data for a different session is even working fine.

What I mean by this is

1. if I catch this exception,

2. make a new session from the same, unchanged KieBase,

3. and try again

- then - 

there is no exception the 2nd time through for the same inserts.

I've also noted that the "Caused by: java.lang.IllegalArgumentException" is not giving me much information like typical java.lang.reflect.Method#invoke failures do.  This is because of the JVM has optimized this reflective call at this point, as seen by the line "at sun.reflect.GeneratedMethodAccessor15.invoke(Unknown Source)".

This leads me to believe that this reflective call has already happened successfully many times at this point.  However, at some point the 

"at org.mvel2.optimizers.impl.refl.ReflectiveAccessorOptimizer.getMethod(ReflectiveAccessorOptimizer.java:1097)" 

logic calls the method incorrectly.  - This is my assumption.

I have debugged this code that has failed sporadically, and I have walked through the MVEL compilation steps involved on all the lines listed above in this stacktrace.  They are always doing "the right things" from what I have observed.

I've searched around for related issues, but have failed to find any at this point.  I cannot give a packaged jar that recreates the issue because it only happens a very small fraction of the time in the real environment that I have seen it in.

My a "small fraction of the time" I mean this error occurs probably once in 1 million+ KieSessions created from the around  1000 "duplciate" KieBases.  The KieBase is compiled in a distributed environment, so it is compiled around 1000 times and around 1 million KieSessions are created from those 1000 KieBase "duplicates".  That makes it something like ~1000 KieSessions per KieBase.  However the KieBase always has its global variables defined the same way with the exact same DRL resource and rules/queries.

However, as I have suggested above, I do not think any KieBase is "corrupted" since I think that most sessions that are "spawned from the same KieBase that are successful, with only a single one failing sporadically and only sometimes.

I hope this makes some sense as far as what my issue is.  I'm just looking to see if there is any insight available into what could cause this unlikely, and maybe even nondeterministic failure, around the stack I have above.  

I appreciate the feedback.

[Mike Rodriguez]

Sorry, I had a small typo in this message, the exception message has this:

[Near : {... true == fn_1.invoke(this) ....}]

Not `fn_1657` I just made a copy/paste error.

The global variable that is sometimes failing to be reflectively invoked is from the rule line:

 b : some.org.model.MyClass(true == fn_1.invoke(this))

Sorry for the confusion.

[Mark Proctor]

what version of Drools? And have you tried this on a master snapshot to see if it’s fixed:

http://downloads.jboss.org/drools/release/snapshot/master/

Mark

-- 
You received this message because you are subscribed to the Google Groups "Drools Usage" group.
To unsubscribe from this group and stop receiving emails from it, send an email to drools-usage...@googlegroups.com.
To post to this group, send email to drools...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/drools-usage/7eda8f5f-37fd-45f1-a884-0c5bf8809abf%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Mike Rodriguez]

Sorry, I should have included the version in the original post. 

It is version 6.1.0.CR2.  I believe that uses MVEL version 2.1.9.Final transitively.

I have not been able to try against the most recent version of Drools yet.

This error does not occur frequently so it would take a lot of repeated runs on a new version to understand if the issue was still there or not.  The probability is somewhere really low around <10% right now, I think maybe even <5%.

I'd like to try against a newer version of Drools soon.  Are there any known issues with any of this or MVEL that may have been addressed recently that relate to this sort of error?

Thanks again.

[Davide Sottara]

I think the latest version of Mvel is 2.2.2, and many issues have been solved both in Drools and Mvel.

To view this discussion on the web visit https://groups.google.com/d/msgid/drools-usage/cfbfd65c-c870-4a3d-8cff-96569e653904%40googlegroups.com.

[Mike Rodriguez]

To follow up on this, we upgraded to Drools version 6.2.0.CR4 a few weeks ago.  This brings along a later MVEL as was suggested by Davide.  So far we have not seen anymore occurrences of this failure.  The failure used to occur at least a few times per week, so the absence of any failure at this point is a good sign that something changed recently has fixed the issue.

So to conclude this:

Drools version 6.1.0.CR2 - seems to have this intermittent failure within the MVEL reflection flow.

Drools version 6.2.0.CR4 - appears to have fixed this issue, since we are no longer seeing these failures after many runs on our production data.

I never was able to track down the root cause though.

Thanks for the feedback and help on this.

- Mike Rodriguez -

[Mark Proctor]

Mario did some work on MVEL to remove use of  LocalThread. So if you have thread stuff going on, it might be related to that.

Mark

To view this discussion on the web visit https://groups.google.com/d/msgid/drools-usage/72684848-3d03-4f8e-8058-922365b35f20%40googlegroups.com.