Intermittent NPE in OptaPlanner constraint streams

Viewed 71

I've been struggling to reproduce this exception, which is unfortunately an intermittent failure in an OptaPlanner project I'm leading. Any insights would be much appreciated:

java.lang.IllegalStateException: The move thread with moveThreadIndex (2) has thrown an exception. Relayed here in the parent thread.
    at org.optaplanner.core.impl.heuristic.thread.OrderByMoveIndexBlockingQueue.take(OrderByMoveIndexBlockingQueue.java:147)
    at org.optaplanner.core.impl.localsearch.decider.MultiThreadedLocalSearchDecider.forageResult(MultiThreadedLocalSearchDecider.java:195)
    at org.optaplanner.core.impl.localsearch.decider.MultiThreadedLocalSearchDecider.decideNextStep(MultiThreadedLocalSearchDecider.java:160)
    at org.optaplanner.core.impl.localsearch.DefaultLocalSearchPhase.solve(DefaultLocalSearchPhase.java:88)
    at org.optaplanner.core.impl.solver.AbstractSolver.runPhases(AbstractSolver.java:99)
    at org.optaplanner.core.impl.solver.DefaultSolver.solve(DefaultSolver.java:209)
    at com.greyorange.taskscheduler.Optimizer.optimize(Optimizer.java:99)
    at com.greyorange.taskscheduler.Optimizer.solve(Optimizer.java:54)
    at com.greyorange.taskscheduler.behavior.TwoBotsTests.testTwoBotsTwoTasks(TwoBotsTests.java:197)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:568)
    at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:725)
    at org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131)
    at org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:149)
    at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:140)
    at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestMethod(TimeoutExtension.java:84)
    at org.junit.jupiter.engine.execution.ExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(ExecutableInvoker.java:115)
    at org.junit.jupiter.engine.execution.ExecutableInvoker.lambda$invoke$0(ExecutableInvoker.java:105)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37)
    at org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:104)
    at org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:98)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$7(TestMethodTestDescriptor.java:214)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:210)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:135)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:66)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:151)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
    at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
    at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
    at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:35)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:54)
    at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:220)
    at org.junit.platform.launcher.core.DefaultLauncher.lambda$execute$6(DefaultLauncher.java:188)
    at org.junit.platform.launcher.core.DefaultLauncher.withInterceptedStreams(DefaultLauncher.java:202)
    at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:181)
    at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:128)
    at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invokeAllTests(JUnitPlatformProvider.java:150)
    at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invoke(JUnitPlatformProvider.java:124)
    at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:384)
    at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:345)
    at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:126)
    at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:418)
Caused by: org.kie.api.runtime.rule.ConsequenceException: Exception executing consequence for rule "Minimize makespan" in com.greyorange.taskscheduler.costs: java.lang.NullPointerException: Cannot invoke "org.optaplanner.constraint.streams.common.inliner.WeightedScoreImpacter.impactScore(int, org.optaplanner.constraint.streams.common.inliner.JustificationsSupplier)" because "scoreImpacter" is null
    at org.drools.core.runtime.rule.impl.DefaultConsequenceExceptionHandler.handleException(DefaultConsequenceExceptionHandler.java:39)
    at org.drools.kiesession.agenda.DefaultAgenda.handleException(DefaultAgenda.java:935)
    at org.drools.core.phreak.RuleExecutor.innerFireActivation(RuleExecutor.java:460)
    at org.drools.core.phreak.RuleExecutor.evaluateNetworkAndFire(RuleExecutor.java:101)
    at org.drools.core.concurrent.AbstractRuleEvaluator.internalEvaluateAndFire(AbstractRuleEvaluator.java:33)
    at org.drools.core.concurrent.SequentialRuleEvaluator.evaluateAndFire(SequentialRuleEvaluator.java:43)
    at org.drools.kiesession.agenda.DefaultAgenda.fireLoop(DefaultAgenda.java:748)
    at org.drools.kiesession.agenda.DefaultAgenda.internalFireAllRules(DefaultAgenda.java:695)
    at org.drools.kiesession.agenda.DefaultAgenda.fireAllRules(DefaultAgenda.java:687)
    at org.drools.kiesession.session.StatefulKnowledgeSessionImpl.internalFireAllRules(StatefulKnowledgeSessionImpl.java:1092)
    at org.drools.kiesession.session.StatefulKnowledgeSessionImpl.fireAllRules(StatefulKnowledgeSessionImpl.java:1083)
    at org.drools.kiesession.session.StatefulKnowledgeSessionImpl.fireAllRules(StatefulKnowledgeSessionImpl.java:1075)
    at org.optaplanner.constraint.streams.drools.DroolsConstraintStreamScoreDirector.calculateScore(DroolsConstraintStreamScoreDirector.java:85)
    at org.optaplanner.core.impl.score.director.AbstractScoreDirector.doAndProcessMove(AbstractScoreDirector.java:222)
    at org.optaplanner.core.impl.heuristic.thread.MoveThreadRunner.run(MoveThreadRunner.java:147)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
    at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: java.lang.NullPointerException: Cannot invoke "org.optaplanner.constraint.streams.common.inliner.WeightedScoreImpacter.impactScore(int, org.optaplanner.constraint.streams.common.inliner.JustificationsSupplier)" because "scoreImpacter" is null
    at org.optaplanner.constraint.streams.drools.common.AbstractRuleContext.runConsequence(AbstractRuleContext.java:51)
    at org.optaplanner.constraint.streams.drools.common.UniRuleContext.lambda$newRuleBuilder$c987a6e2$1(UniRuleContext.java:43)
    at org.drools.model.functions.Block3$Impl.execute(Block3.java:40)
    at org.drools.modelcompiler.consequence.LambdaConsequence.evaluate(LambdaConsequence.java:76)
    at org.drools.core.phreak.RuleExecutor.innerFireActivation(RuleExecutor.java:454)
    ... 17 common frames omitted

The constraint "minimize makespan" which is referenced in the stack trace is as follows:

  protected Constraint minimizeMakespan(ConstraintFactory constraintFactory) {
    return constraintFactory.forEach(CandidateAssignment.class)
        .filter(CandidateAssignment::isAssigned)
        .filter(assignment -> !assignment.isCommitted())
        .penalizeConfigurable("Minimize makespan",
            (candidateAssignment) -> candidateAssignment.getLastTimeSampleIndex() * ApplicationProperties.PERIOD_SECONDS());
  }

The first filter removes any unassigned planning entity (checking that both the planning variables of the entity are non-null, as both planning variables are nullable). There should be no chance of NPE in that method.

2 Answers

The move thread with moveThreadIndex (2) has thrown an exception. Relayed here in the parent thread.

Ignore this wrapping. It just means the exception did occur in a child thread (a move thread) and is relayed on the solver thread for your convenience.

It neither proves or disproves it's a concurrency bug.

NullPointerException: Cannot invoke ...WeightedScoreImpacter.impactScore(...)" because "scoreImpacter" is null

Ok, that's is weird, because the scoreImpacter is never null.

A) So it could be a concurrency bug (for example if the scoreImpacter field is set after construction and then run another thread without a CPU cache refresh (see Java Concurrency in practice)). But that's very, very unlikely. It would mean KieBase doesn't do a form of synchronized/volatile before starting to create KieSessions.

B) What Lukas suggested: a zero weight constraint, that somehow got build anyway and no fail fasts happened. But than it would reproduce every time and should reproduce with moveThreadCount=0 too.

Either way, only a reproducer can help at this point. It should be reproducible on every run if you're using environmentMode=REPRODUCIBLE and not using Simulated Annealing (or do use SA but switch to stepCount termination).

I believe that this was a bug in Drools that was recently fixed. Please retry with OptaPlanner 8.23.0.Final, when we release it in the coming weeks.

(That said, without a code reproducer, I can not be sure. I only know an issue was fixed with similar symptoms.)

Related