Occasional test failure in Event Processor

[schbetsy]

[info] Event processor
[info] - must process upload start message from event stream *** FAILED ***
[info]   java.lang.AssertionError: timeout (3 seconds) waiting for 1 messages on DebugFilter(Some(akka://test-system/user/$a),Left(Upload started for submission 12345-2017-1),true)
[info]   at akka.testkit.EventFilter.intercept(TestEventListener.scala:114)
[info]   at hmda.api.processing.LocalHmdaEventProcessorSpec$$anonfun$1$$anonfun$apply$mcV$sp$1.apply$mcV$sp(LocalHmdaEventProcessorSpec.scala:37)
[info]   at hmda.api.processing.LocalHmdaEventProcessorSpec$$anonfun$1$$anonfun$apply$mcV$sp$1.apply(LocalHmdaEventProcessorSpec.scala:35)
[info]   at hmda.api.processing.LocalHmdaEventProcessorSpec$$anonfun$1$$anonfun$apply$mcV$sp$1.apply(LocalHmdaEventProcessorSpec.scala:35)
[info]   at org.scalatest.OutcomeOf$class.outcomeOf(OutcomeOf.scala:85)
[info]   at org.scalatest.OutcomeOf$.outcomeOf(OutcomeOf.scala:104)
[info]   at org.scalatest.Transformer.apply(Transformer.scala:22)
[info]   at org.scalatest.Transformer.apply(Transformer.scala:20)
[info]   at org.scalatest.WordSpecLike$$anon$1.apply(WordSpecLike.scala:1078)
[info]   at org.scalatest.TestSuite$class.withFixture(TestSuite.scala:196)
[info]   ...

Found by Travis. link.

[lgdean]

I've been able to reproduce a similar (but opposite) failure locally, too (but not predictably). I've seen it happen sometimes when running just that class in IntelliJ, which is faster than doing all of sbt test, at least.

My failure looks like:

[info] - must process parse completed message from event stream *** FAILED ***
[info]   java.lang.AssertionError: received 1 excess messages on DebugFilter(Some(akka://test-system/user/$a),Left(Parsing completed for 12345-2017-1),true)
[info]   at akka.testkit.EventFilter.intercept(TestEventListener.scala:116)
[info]   at hmda.api.processing.LocalHmdaEventProcessorSpec$$anonfun$1$$anonfun$apply$mcV$sp$5.apply$mcV$sp(LocalHmdaEventProcessorSpec.scala:51)
[info]   at hmda.api.processing.LocalHmdaEventProcessorSpec$$anonfun$1$$anonfun$apply$mcV$sp$5.apply(LocalHmdaEventProcessorSpec.scala:49)
[info]   at hmda.api.processing.LocalHmdaEventProcessorSpec$$anonfun$1$$anonfun$apply$mcV$sp$5.apply(LocalHmdaEventProcessorSpec.scala:49)
[info]   at org.scalatest.OutcomeOf$class.outcomeOf(OutcomeOf.scala:85)
[info]   at org.scalatest.OutcomeOf$.outcomeOf(OutcomeOf.scala:104)
[info]   at org.scalatest.Transformer.apply(Transformer.scala:22)
[info]   at org.scalatest.Transformer.apply(Transformer.scala:20)
[info]   at org.scalatest.WordSpecLike$$anon$1.apply(WordSpecLike.scala:1078)
[info]   at org.scalatest.TestSuite$class.withFixture(TestSuite.scala:196)
[info]   ...

On the command line with sbt test I noticed that, when it passes, this line appears in the console output, as the last of 10 debug lines:
[DEBUG] [08/18/2016 15:54:11.660] [test-system-akka.actor.default-dispatcher-6] [akka://test-system/user/$a] Parsing completed for 12345-2017-1
But when the test fails, that line does not appear. I found it surprising, because the failure message makes it sound like that debug message is appearing too often. (But maybe it means that some extra message is sometimes getting filtered and counted, but other times getting printed? I don't know the details well enough to do more than guess.)

[jmarin]

I've kicked the build again in Travis and it passes. Only explanation I have at this point in time is that the system got busy and we hit the 3 second timeout for this response. I don't have an answer for IntelliJ local run failures, it's something I haven't seen before since I never run tests with the IDE.

[lgdean]

It's not just in IntelliJ: I noticed it first in sbt test and then ran it in the IDE as a convenient way to run just that class, rather than the whole thing.

[kgudel]

I have tried to reproduce this without success and so I'm closing the issue.

[lgdean]

I'm still getting the failure from the comment from time to time (at least once a day, and twice so far today), FWIW.

Also, it sounds like an issue similar to the original (but for upload complete rather than start) happened in #532.