Transient failure of AppenderatorDriverTest.testPublishPerRow

[leventov]

Running io.druid.segment.realtime.appenderator.AppenderatorDriverTest
Tests run: 5, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 5.063 sec <<< FAILURE! - in io.druid.segment.realtime.appenderator.AppenderatorDriverTest
testPublishPerRow(io.druid.segment.realtime.appenderator.AppenderatorDriverTest)  Time elapsed: 1.428 sec  <<< ERROR!
java.util.concurrent.TimeoutException
	at java.util.concurrent.FutureTask.get(FutureTask.java:205)
	at io.druid.segment.realtime.appenderator.AppenderatorDriverTest.testPublishPerRow(AppenderatorDriverTest.java:250)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:483)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
	at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:367)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:274)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:238)
	at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:161)
	at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:290)
	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:242)
	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:121)

[jihoonson]

Another failure.

Tests run: 5, Failures: 0, Errors: 2, Skipped: 0, Time elapsed: 7.164 sec <<< FAILURE! - in io.druid.segment.realtime.appenderator.AppenderatorDriverTest
testMaxRowsPerSegment(io.druid.segment.realtime.appenderator.AppenderatorDriverTest)  Time elapsed: 2.846 sec  <<< ERROR!
java.util.concurrent.TimeoutException
	at java.util.concurrent.FutureTask.get(FutureTask.java:205)
	at io.druid.segment.realtime.appenderator.AppenderatorDriverTest.testMaxRowsPerSegment(AppenderatorDriverTest.java:184)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:483)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
	at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:367)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:274)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:238)
	at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:161)
	at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:290)
	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:242)
	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:121)

[leventov]

@jihoonson doesn't seem to be fixed, https://travis-ci.org/druid-io/druid/jobs/243476564 just failed with

io.druid.segment.realtime.appenderator.AppenderatorDriverTest
testPublishPerRow(io.druid.segment.realtime.appenderator.AppenderatorDriverTest)  Time elapsed: 5.526 sec  <<< ERROR!
java.util.concurrent.TimeoutException
	at java.util.concurrent.FutureTask.get(FutureTask.java:205)
	at io.druid.segment.realtime.appenderator.AppenderatorDriverTest.testPublishPerRow(AppenderatorDriverTest.java:250)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:483)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
	at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:367)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:274)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:238)
	at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:161)
	at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:290)
	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:242)
	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:121)

[gianm]

Travis seems to be slow beyond belief recently. Even tests that succeed seem to be taking longer than normal. I wonder if this is related.

[jihoonson]

@leventov hmm I'm looking into it.

[jihoonson]

@gianm I can see the below error which looks to relate to #4365 when running AppenderatorDriverTest.

2017-06-16T02:28:09,453 WARN [foo-incremental-persist] io.druid.segment.IndexIO - Failed to load metadata for segment [/tmp/1497580089435-0/foo_2000-01-01T00:00:00.000Z_2000-01-01T01:00:00.000Z_abc123/0]
com.fasterxml.jackson.databind.JsonMappingException: No 'injectableValues' configured, can not inject value with id [io.druid.math.expr.ExprMacroTable] (through reference chain: io.druid.segment.Metadata["aggregators"]->Object[][0])
	at com.fasterxml.jackson.databind.JsonMappingException.wrapWithPath(JsonMappingException.java:210) ~[jackson-databind-2.4.6.jar:2.4.6]
	at com.fasterxml.jackson.databind.JsonMappingException.wrapWithPath(JsonMappingException.java:189) ~[jackson-databind-2.4.6.jar:2.4.6]
	at com.fasterxml.jackson.databind.deser.std.ObjectArrayDeserializer.deserialize(ObjectArrayDeserializer.java:160) ~[jackson-databind-2.4.6.jar:2.4.6]
	at com.fasterxml.jackson.databind.deser.std.ObjectArrayDeserializer.deserialize(ObjectArrayDeserializer.java:17) ~[jackson-databind-2.4.6.jar:2.4.6]
	at com.fasterxml.jackson.databind.deser.SettableBeanProperty.deserialize(SettableBeanProperty.java:538) ~[jackson-databind-2.4.6.jar:2.4.6]
	at com.fasterxml.jackson.databind.deser.impl.MethodProperty.deserializeAndSet(MethodProperty.java:99) ~[jackson-databind-2.4.6.jar:2.4.6]
	at com.fasterxml.jackson.databind.deser.BeanDeserializer.vanillaDeserialize(BeanDeserializer.java:238) ~[jackson-databind-2.4.6.jar:2.4.6]
	at com.fasterxml.jackson.databind.deser.BeanDeserializer.deserialize(BeanDeserializer.java:118) ~[jackson-databind-2.4.6.jar:2.4.6]
	at com.fasterxml.jackson.databind.ObjectMapper._readMapAndClose(ObjectMapper.java:3066) ~[jackson-databind-2.4.6.jar:2.4.6]
	at com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:2230) ~[jackson-databind-2.4.6.jar:2.4.6]
	at io.druid.segment.IndexIO$V9IndexLoader.load(IndexIO.java:1006) [classes/:?]
	at io.druid.segment.IndexIO.loadIndex(IndexIO.java:220) [classes/:?]
	at io.druid.segment.realtime.appenderator.AppenderatorImpl.persistHydrant(AppenderatorImpl.java:1020) [classes/:?]
	at io.druid.segment.realtime.appenderator.AppenderatorImpl.access$200(AppenderatorImpl.java:96) [classes/:?]
	at io.druid.segment.realtime.appenderator.AppenderatorImpl$2.doCall(AppenderatorImpl.java:387) [classes/:?]
	at io.druid.common.guava.ThreadRenamingCallable.call(ThreadRenamingCallable.java:44) [classes/:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_131]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_131]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_131]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_131]
Caused by: java.lang.IllegalStateException: No 'injectableValues' configured, can not inject value with id [io.druid.math.expr.ExprMacroTable]
	at com.fasterxml.jackson.databind.DeserializationContext.findInjectableValue(DeserializationContext.java:291) ~[jackson-databind-2.4.6.jar:2.4.6]
	at com.fasterxml.jackson.databind.deser.impl.PropertyValueBuffer.inject(PropertyValueBuffer.java:66) ~[jackson-databind-2.4.6.jar:2.4.6]
	at com.fasterxml.jackson.databind.deser.impl.PropertyBasedCreator.startBuilding(PropertyBasedCreator.java:160) ~[jackson-databind-2.4.6.jar:2.4.6]
	at com.fasterxml.jackson.databind.deser.BeanDeserializer._deserializeUsingPropertyBased(BeanDeserializer.java:331) ~[jackson-databind-2.4.6.jar:2.4.6]
	at com.fasterxml.jackson.databind.deser.BeanDeserializerBase.deserializeFromObjectUsingNonDefault(BeanDeserializerBase.java:1064) ~[jackson-databind-2.4.6.jar:2.4.6]
	at com.fasterxml.jackson.databind.deser.BeanDeserializer.deserializeFromObject(BeanDeserializer.java:264) ~[jackson-databind-2.4.6.jar:2.4.6]
	at com.fasterxml.jackson.databind.deser.BeanDeserializer._deserializeOther(BeanDeserializer.java:156) ~[jackson-databind-2.4.6.jar:2.4.6]
	at com.fasterxml.jackson.databind.deser.BeanDeserializer.deserialize(BeanDeserializer.java:126) ~[jackson-databind-2.4.6.jar:2.4.6]
	at com.fasterxml.jackson.databind.jsontype.impl.AsPropertyTypeDeserializer._deserializeTypedForId(AsPropertyTypeDeserializer.java:113) ~[jackson-databind-2.4.6.jar:2.4.6]
	at com.fasterxml.jackson.databind.jsontype.impl.AsPropertyTypeDeserializer.deserializeTypedFromObject(AsPropertyTypeDeserializer.java:84) ~[jackson-databind-2.4.6.jar:2.4.6]
	at com.fasterxml.jackson.databind.deser.AbstractDeserializer.deserializeWithType(AbstractDeserializer.java:132) ~[jackson-databind-2.4.6.jar:2.4.6]
	at com.fasterxml.jackson.databind.deser.std.ObjectArrayDeserializer.deserialize(ObjectArrayDeserializer.java:151) ~[jackson-databind-2.4.6.jar:2.4.6]
	... 17 more

Do you think this might be a reason for slowing down tests?

[gianm]

Hmm, I wouldn't think so, but could still check the before and after times to be sure. Gian

…

On Jun 15, 2017, at 19:37, Jihoon Son ***@***.***> wrote: @gianm I can see the below error which looks to relate to #4365 when running AppenderatorDriverTest. 2017-06-16T02:28:09,453 WARN [foo-incremental-persist] io.druid.segment.IndexIO - Failed to load metadata for segment [/tmp/1497580089435-0/foo_2000-01-01T00:00:00.000Z_2000-01-01T01:00:00.000Z_abc123/0] com.fasterxml.jackson.databind.JsonMappingException: No 'injectableValues' configured, can not inject value with id [io.druid.math.expr.ExprMacroTable] (through reference chain: io.druid.segment.Metadata["aggregators"]->Object[][0]) at com.fasterxml.jackson.databind.JsonMappingException.wrapWithPath(JsonMappingException.java:210) ~[jackson-databind-2.4.6.jar:2.4.6] at com.fasterxml.jackson.databind.JsonMappingException.wrapWithPath(JsonMappingException.java:189) ~[jackson-databind-2.4.6.jar:2.4.6] at com.fasterxml.jackson.databind.deser.std.ObjectArrayDeserializer.deserialize(ObjectArrayDeserializer.java:160) ~[jackson-databind-2.4.6.jar:2.4.6] at com.fasterxml.jackson.databind.deser.std.ObjectArrayDeserializer.deserialize(ObjectArrayDeserializer.java:17) ~[jackson-databind-2.4.6.jar:2.4.6] at com.fasterxml.jackson.databind.deser.SettableBeanProperty.deserialize(SettableBeanProperty.java:538) ~[jackson-databind-2.4.6.jar:2.4.6] at com.fasterxml.jackson.databind.deser.impl.MethodProperty.deserializeAndSet(MethodProperty.java:99) ~[jackson-databind-2.4.6.jar:2.4.6] at com.fasterxml.jackson.databind.deser.BeanDeserializer.vanillaDeserialize(BeanDeserializer.java:238) ~[jackson-databind-2.4.6.jar:2.4.6] at com.fasterxml.jackson.databind.deser.BeanDeserializer.deserialize(BeanDeserializer.java:118) ~[jackson-databind-2.4.6.jar:2.4.6] at com.fasterxml.jackson.databind.ObjectMapper._readMapAndClose(ObjectMapper.java:3066) ~[jackson-databind-2.4.6.jar:2.4.6] at com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:2230) ~[jackson-databind-2.4.6.jar:2.4.6] at io.druid.segment.IndexIO$V9IndexLoader.load(IndexIO.java:1006) [classes/:?] at io.druid.segment.IndexIO.loadIndex(IndexIO.java:220) [classes/:?] at io.druid.segment.realtime.appenderator.AppenderatorImpl.persistHydrant(AppenderatorImpl.java:1020) [classes/:?] at io.druid.segment.realtime.appenderator.AppenderatorImpl.access$200(AppenderatorImpl.java:96) [classes/:?] at io.druid.segment.realtime.appenderator.AppenderatorImpl$2.doCall(AppenderatorImpl.java:387) [classes/:?] at io.druid.common.guava.ThreadRenamingCallable.call(ThreadRenamingCallable.java:44) [classes/:?] at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_131] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_131] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_131] at java.lang.Thread.run(Thread.java:748) [?:1.8.0_131] Caused by: java.lang.IllegalStateException: No 'injectableValues' configured, can not inject value with id [io.druid.math.expr.ExprMacroTable] at com.fasterxml.jackson.databind.DeserializationContext.findInjectableValue(DeserializationContext.java:291) ~[jackson-databind-2.4.6.jar:2.4.6] at com.fasterxml.jackson.databind.deser.impl.PropertyValueBuffer.inject(PropertyValueBuffer.java:66) ~[jackson-databind-2.4.6.jar:2.4.6] at com.fasterxml.jackson.databind.deser.impl.PropertyBasedCreator.startBuilding(PropertyBasedCreator.java:160) ~[jackson-databind-2.4.6.jar:2.4.6] at com.fasterxml.jackson.databind.deser.BeanDeserializer._deserializeUsingPropertyBased(BeanDeserializer.java:331) ~[jackson-databind-2.4.6.jar:2.4.6] at com.fasterxml.jackson.databind.deser.BeanDeserializerBase.deserializeFromObjectUsingNonDefault(BeanDeserializerBase.java:1064) ~[jackson-databind-2.4.6.jar:2.4.6] at com.fasterxml.jackson.databind.deser.BeanDeserializer.deserializeFromObject(BeanDeserializer.java:264) ~[jackson-databind-2.4.6.jar:2.4.6] at com.fasterxml.jackson.databind.deser.BeanDeserializer._deserializeOther(BeanDeserializer.java:156) ~[jackson-databind-2.4.6.jar:2.4.6] at com.fasterxml.jackson.databind.deser.BeanDeserializer.deserialize(BeanDeserializer.java:126) ~[jackson-databind-2.4.6.jar:2.4.6] at com.fasterxml.jackson.databind.jsontype.impl.AsPropertyTypeDeserializer._deserializeTypedForId(AsPropertyTypeDeserializer.java:113) ~[jackson-databind-2.4.6.jar:2.4.6] at com.fasterxml.jackson.databind.jsontype.impl.AsPropertyTypeDeserializer.deserializeTypedFromObject(AsPropertyTypeDeserializer.java:84) ~[jackson-databind-2.4.6.jar:2.4.6] at com.fasterxml.jackson.databind.deser.AbstractDeserializer.deserializeWithType(AbstractDeserializer.java:132) ~[jackson-databind-2.4.6.jar:2.4.6] at com.fasterxml.jackson.databind.deser.std.ObjectArrayDeserializer.deserialize(ObjectArrayDeserializer.java:151) ~[jackson-databind-2.4.6.jar:2.4.6] ... 17 more Do you think this might be a reason for slowing down tests? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or mute the thread.

[stale]

This issue has been marked as stale due to 280 days of inactivity. It will be closed in 2 weeks if no further activity occurs. If this issue is still relevant, please simply write any comment. Even if closed, you can still revive the issue at any time or discuss it on the dev@druid.apache.org list. Thank you for your contributions.