when attempting to interact (create acceleration, query…) with a certain table we got
com.dremio.common.exceptions.UserException: General failure during substitutions
at com.dremio.common.exceptions.UserException$Builder.build(UserException.java:746) ~[dremio-common-2.1.6-201809161906440178-edb5b4d.jar:2.1.6-201809161906440178-edb5b4d]
at com.dremio.exec.planner.acceleration.substitution.DremioSubstitutionProvider.findSubstitutions(DremioSubstitutionProvider.java:157) [dremio-extra-sabot-kernel-2.1.6-201809161906440178-edb5b4d.jar:2.1.6-201809161906440178-edb5b4d]
at com.dremio.exec.planner.acceleration.substitution.AccelerationAwareSubstitutionProvider.findSubstitutions(AccelerationAwareSubstitutionProvider.java:67) [dremio-sabot-kernel-2.1.6-201809161906440178-edb5b4d.jar:2.1.6-201809161906440178-edb5b4d]
at com.dremio.exec.planner.DremioVolcanoPlanner.registerMaterializations(DremioVolcanoPlanner.java:70) [dremio-sabot-kernel-2.1.6-201809161906440178-edb5b4d.jar:2.1.6-201809161906440178-edb5b4d]
at org.apache.calcite.plan.volcano.VolcanoPlanner.findBestExp(VolcanoPlanner.java:599) [calcite-core-1.16.0-201809101700460107-acbf677.jar:1.16.0-201809101700460107-acbf677]
at org.apache.calcite.tools.Programs$RuleSetProgram.run(Programs.java:368) [calcite-core-1.16.0-201809101700460107-acbf677.jar:1.16.0-201809101700460107-acbf677]
at com.dremio.exec.planner.sql.handlers.PrelTransformer.transform(PrelTransformer.java:454) [dremio-sabot-kernel-2.1.6-201809161906440178-edb5b4d.jar:2.1.6-201809161906440178-edb5b4d]
at com.dremio.exec.planner.sql.handlers.PrelTransformer.convertToDrel(PrelTransformer.java:223) [dremio-sabot-kernel-2.1.6-201809161906440178-edb5b4d.jar:2.1.6-201809161906440178-edb5b4d]
at com.dremio.exec.planner.sql.handlers.PrelTransformer.convertToDrel(PrelTransformer.java:281) [dremio-sabot-kernel-2.1.6-201809161906440178-edb5b4d.jar:2.1.6-201809161906440178-edb5b4d]
at com.dremio.exec.planner.sql.handlers.query.NormalHandler.getPlan(NormalHandler.java:47) [dremio-sabot-kernel-2.1.6-201809161906440178-edb5b4d.jar:2.1.6-201809161906440178-edb5b4d]
at com.dremio.exec.planner.sql.handlers.commands.HandlerToExec.plan(HandlerToExec.java:69) [dremio-sabot-kernel-2.1.6-201809161906440178-edb5b4d.jar:2.1.6-201809161906440178-edb5b4d]
at com.dremio.exec.work.foreman.AttemptManager.run(AttemptManager.java:291) [dremio-sabot-kernel-2.1.6-201809161906440178-edb5b4d.jar:2.1.6-201809161906440178-edb5b4d]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_181]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_181]
at java.lang.Thread.run(Thread.java:748) [na:1.8.0_181]
Caused by: java.lang.ArrayIndexOutOfBoundsException: 43
We were able to further narrow down the problem. The exception only occurs, when we enable an aggregation-reflection on a virtual composite datase from two seperate data-sources. When this reflection is enabled, some, but not all, other reflections fail (they arent accelerated and “General failure during substitutions” is thrown). If this reflection disabled, all reflections work.
A) ace8ca41-918c-4f97-8292-d683b6202ebf: Is a query that has completed in < 1s
B) 1432bd60-1018-41f9-9eeb-02fe5318b393: Is a refresh reflection that seems to have been running . Was it cancelled?
C) 4b9d8f00-7752-4583-b698-ae198c47bdfe: Is a refresh reflection that has completed in 8s
Is your concern that the query did not use the reflection? If yes which of the two reflections are you expecting to be used? A) or B)?
the problem is that as soon as aggregation-reflection 4b9d8f00-7752-4583-b698-ae198c47bdfe is enabled, all querys (even from different sources and spaces) which were previously accelerated, arent accelerated anymore and “com.dremio.common.exceptions.UserException: General failure during substitutions … Caused by: java.lang.ArrayIndexOutOfBoundsException: 43” is thrown when the querys are being runned.
When 4b9d8f00-7752-4583-b698-ae198c47bdfe is disabled, all other querys are accelerated again and the error is not thrown anymore.
Awesome, When that error happens, can you please click on jobs and you will see a failed job. Send us the profile of that failed job. We need to look at the complete stack trace
There are no profiles from failing jobs, because there are no failing jobs. As i already wrote, the only thing that happens is, that jobs arent accelerated anymore.
The “General failure during substitutions”-error isnt visible on the dremio frontend. It only manifests itself in the form of querys not beeing accelerated, as i already wrote.
2018-10-19 08:24:44,209 [FABRIC-rpc-event-queue] INFO c.d.s.e.rpc.CoordToExecHandlerImpl - Received remote fragment start instruction for 24368752-b703-c7b8-7825-a8e3c2af6800:0:0
2018-10-19 08:24:44,210 [FABRIC-rpc-event-queue] INFO c.d.s.e.rpc.CoordToExecHandlerImpl - Received remote fragment start instruction for 24368752-b703-c7b8-7825-a8e3c2af6800:1:0
2018-10-19 08:24:44,583 [e0 - 24368752-b703-c7b8-7825-a8e3c2af6800:frag:0:0] INFO c.d.s.e.f.FragmentStatusReporter - 24368752-b703-c7b8-7825-a8e3c2af6800:0:0: State to report: FINISHED
2018-10-19 08:24:44,584 [e1 - 24368752-b703-c7b8-7825-a8e3c2af6800:frag:1:0] INFO c.d.s.e.f.FragmentStatusReporter - 24368752-b703-c7b8-7825-a8e3c2af6800:1:0: State to report: FINISHED
2018-10-19 08:24:44,585 [FABRIC-rpc-event-queue] INFO query.logger - {“queryId”:“24368752-b703-c7b8-7825-a8e3c2af6800”,“schema”:“bdb_space”,“queryText”:“SELECT *\nFROM bdb_space.formular”,“start”:1539930284010,“finish”:1539930284585,“outcome”:“COMPLETED”,“username”:“mathias.ellermann”,“commandDescription”:“execute; query”}
2018-10-19 08:24:47,166 [24368750-421d-d0c2-8eeb-0aa10bd81900:foreman] INFO c.d.e.p.a.s.DremioSubstitutionProvider - User Error Occurred [ErrorId: 077fb3f2-72ed-483b-b02a-f66515cd1d3b]
com.dremio.common.exceptions.UserException: General failure during substitutions
at com.dremio.common.exceptions.UserException$Builder.build(UserException.java:746) ~[dremio-common-2.1.6-201809161906440178-edb5b4d.jar:2.1.6-201809161906440178-edb5b4d]
at com.dremio.exec.planner.acceleration.substitution.DremioSubstitutionProvider.findSubstitutions(DremioSubstitutionProvider.java:157) [dremio-extra-sabot-kernel-2.1.6-201809161906440178-edb5b4d.jar:2.1.6-201809161906440178-edb5b4d]
at com.dremio.exec.planner.acceleration.substitution.AccelerationAwareSubstitutionProvider.findSubstitutions(AccelerationAwareSubstitutionProvider.java:67) [dremio-sabot-kernel-2.1.6-201809161906440178-edb5b4d.jar:2.1.6-201809161906440178-edb5b4d]
at com.dremio.exec.planner.DremioVolcanoPlanner.registerMaterializations(DremioVolcanoPlanner.java:70) [dremio-sabot-kernel-2.1.6-201809161906440178-edb5b4d.jar:2.1.6-201809161906440178-edb5b4d]
at org.apache.calcite.plan.volcano.VolcanoPlanner.findBestExp(VolcanoPlanner.java:599) [calcite-core-1.16.0-201809101700460107-acbf677.jar:1.16.0-201809101700460107-acbf677]
at org.apache.calcite.tools.Programs$RuleSetProgram.run(Programs.java:368) [calcite-core-1.16.0-201809101700460107-acbf677.jar:1.16.0-201809101700460107-acbf677]
at com.dremio.exec.planner.sql.handlers.PrelTransformer.transform(PrelTransformer.java:454) [dremio-sabot-kernel-2.1.6-201809161906440178-edb5b4d.jar:2.1.6-201809161906440178-edb5b4d]
at com.dremio.exec.planner.sql.handlers.PrelTransformer.convertToDrel(PrelTransformer.java:223) [dremio-sabot-kernel-2.1.6-201809161906440178-edb5b4d.jar:2.1.6-201809161906440178-edb5b4d]
at com.dremio.exec.planner.sql.handlers.PrelTransformer.convertToDrel(PrelTransformer.java:281) [dremio-sabot-kernel-2.1.6-201809161906440178-edb5b4d.jar:2.1.6-201809161906440178-edb5b4d]
at com.dremio.exec.planner.sql.handlers.query.NormalHandler.getPlan(NormalHandler.java:47) [dremio-sabot-kernel-2.1.6-201809161906440178-edb5b4d.jar:2.1.6-201809161906440178-edb5b4d]
at com.dremio.exec.planner.sql.handlers.commands.HandlerToExec.plan(HandlerToExec.java:69) [dremio-sabot-kernel-2.1.6-201809161906440178-edb5b4d.jar:2.1.6-201809161906440178-edb5b4d]
at com.dremio.exec.work.foreman.AttemptManager.run(AttemptManager.java:291) [dremio-sabot-kernel-2.1.6-201809161906440178-edb5b4d.jar:2.1.6-201809161906440178-edb5b4d]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_181]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_181]
at java.lang.Thread.run(Thread.java:748) [na:1.8.0_181]
Caused by: java.lang.ArrayIndexOutOfBoundsException: 43
at org.apache.calcite.rel.rules.JoinToMultiJoinRule$InputReferenceCounter.visitInputRef(JoinToMultiJoinRule.java:569) ~[calcite-core-1.16.0-201809101700460107-acbf677.jar:1.16.0-201809101700460107-acbf677]
at org.apache.calcite.rel.rules.JoinToMultiJoinRule$InputReferenceCounter.visitInputRef(JoinToMultiJoinRule.java:560) ~[calcite-core-1.16.0-201809101700460107-acbf677.jar:1.16.0-201809101700460107-acbf677]
at org.apache.calcite.rex.RexInputRef.accept(RexInputRef.java:112) ~[calcite-core-1.16.0-201809101700460107-acbf677.jar:1.16.0-201809101700460107-acbf677]
at org.apache.calcite.rex.RexVisitorImpl.visitCall(RexVisitorImpl.java:80) ~[calcite-core-1.16.0-201809101700460107-acbf677.jar:1.16.0-201809101700460107-acbf677]
at org.apache.calcite.rex.RexCall.accept(RexCall.java:107) ~[calcite-core-1.16.0-201809101700460107-acbf677.jar:1.16.0-201809101700460107-acbf677]
at org.apache.calcite.rel.rules.JoinToMultiJoinRule.addOnJoinFieldRefCounts(JoinToMultiJoinRule.java:486) ~[calcite-core-1.16.0-201809101700460107-acbf677.jar:1.16.0-201809101700460107-acbf677]
at org.apache.calcite.rel.rules.JoinToMultiJoinRule.onMatch(JoinToMultiJoinRule.java:166) ~[calcite-core-1.16.0-201809101700460107-acbf677.jar:1.16.0-201809101700460107-acbf677]
at org.apache.calcite.plan.AbstractRelOptPlanner.fireRule(AbstractRelOptPlanner.java:317) ~[calcite-core-1.16.0-201809101700460107-acbf677.jar:1.16.0-201809101700460107-acbf677]
at org.apache.calcite.plan.hep.HepPlanner.applyRule(HepPlanner.java:556) ~[calcite-core-1.16.0-201809101700460107-acbf677.jar:1.16.0-201809101700460107-acbf677]
at org.apache.calcite.plan.hep.HepPlanner.applyRules(HepPlanner.java:415) ~[calcite-core-1.16.0-201809101700460107-acbf677.jar:1.16.0-201809101700460107-acbf677]
at org.apache.calcite.plan.hep.HepPlanner.executeInstruction(HepPlanner.java:280) ~[calcite-core-1.16.0-201809101700460107-acbf677.jar:1.16.0-201809101700460107-acbf677]
at org.apache.calcite.plan.hep.HepInstruction$RuleCollection.execute(HepInstruction.java:74) ~[calcite-core-1.16.0-201809101700460107-acbf677.jar:1.16.0-201809101700460107-acbf677]
at org.apache.calcite.plan.hep.HepPlanner.executeProgram(HepPlanner.java:211) ~[calcite-core-1.16.0-201809101700460107-acbf677.jar:1.16.0-201809101700460107-acbf677]
at org.apache.calcite.plan.hep.HepPlanner.findBestExp(HepPlanner.java:198) ~[calcite-core-1.16.0-201809101700460107-acbf677.jar:1.16.0-201809101700460107-acbf677]
at com.dremio.exec.planner.acceleration.normalization.RuleAndShuttleNormalizer.normalize(RuleAndShuttleNormalizer.java:67) ~[dremio-extra-sabot-kernel-2.1.6-201809161906440178-edb5b4d.jar:2.1.6-201809161906440178-edb5b4d]
at com.dremio.exec.planner.acceleration.normalization.ChainedNormalizer.normalize(ChainedNormalizer.java:41) ~[dremio-sabot-kernel-2.1.6-201809161906440178-edb5b4d.jar:2.1.6-201809161906440178-edb5b4d]
at com.dremio.exec.planner.acceleration.substitution.DremioSubstitutionProvider.normalizeTarget(DremioSubstitutionProvider.java:287) [dremio-extra-sabot-kernel-2.1.6-201809161906440178-edb5b4d.jar:2.1.6-201809161906440178-edb5b4d]
at com.dremio.exec.planner.acceleration.substitution.DremioSubstitutionProvider.findSubstitutions(DremioSubstitutionProvider.java:129) [dremio-extra-sabot-kernel-2.1.6-201809161906440178-edb5b4d.jar:2.1.6-201809161906440178-edb5b4d]
… 13 common frames omitted