Freeze

Use Case: Freeze

There are asynchronous tests which wait for an event to arrive. When writing the tests for the first time, the code to pass them is not yet implemented, so no event arrives. As a result, the tests will freeze instead of failing with an exception.

References

• Let's Code Dimdwarf #3 starting from 2:20
  • 14:00, write test
  • 14:25, make it compile
  • 15:00, run, exceptions in background thread, tests freeze
  • 17:05, refactoring test, wishing for an async test tool
  • 20:50, implement message encoding, stub
  • 22:15, run, unexpected failure in BG thread, freeze
  • 23:00, implement message encoding, but has a bug and frezees
  • 23:00, add message length to encoding
  • 24:55, run, unexpected failure in BG thread, freeze
  • 25:15, fix bug, run, test fails correctly without freezing
  • 25:55, implement, test pass
• Original commit
• Commits for each step: usecases/freeze

Step 1

• Commit
• step1-stderr_bg-thread-exception.txt
• step1-thread-dump.txt
• step1-thread-dump_unrelated-threads.txt

Wrote a failing test

NetworkSpec.scala @ f939df5

   "When Client sends a logout request" >> {
     out.write(logoutRequest().array)
     queues.waitForMessages()
     queues.processMessagesUntilIdle()
 
     "Actor sends the logout request to Controller" >> {
       assertThat(queues.seenIn(queues.toHub).head, is(LogoutRequest(): Any))
     }
     "Controller logs out the Client" // TODO: keep track of which clients are connected
 
     "Controller sends a logout message to Actor" >> {
       assertThat(queues.seenIn(toNetwork).head, is(LogoutSuccess(): Any))
     }
     "Actor sends the logout message to Client" >> {
+      assertThat(nextMessage(in), is(logoutSuccess()))
     }
   }

SimpleSgsProtocolReferenceMessages.scala @ f939df5

     asIoBuffer(Array[Byte](SimpleSgsProtocol.LOGOUT_REQUEST))
   }
 
+  def logoutSuccess(): IoBuffer = {
+    asIoBuffer(Array[Byte](SimpleSgsProtocol.LOGOUT_SUCCESS))
+  }
+
   private def asIoBuffer(bytes: Array[Byte]): IoBuffer = {
     IoBuffer.allocate(2 + bytes.length).
             putShort(bytes.length.asInstanceOf[Short]).

Run tests: the test freezes, the following stack trace is printed to stderr from a background thread

Console output

23.2.2011 23:25:19 net.orfjackal.dimdwarf.net.NetworkActor start
INFO: Begin listening on port 51992
23.2.2011 23:25:29 org.apache.mina.filter.logging.LoggingFilter log
WARNING: EXCEPTION :
org.apache.mina.filter.codec.ProtocolEncoderException: scala.MatchError: LogoutSuccess()
	at org.apache.mina.filter.codec.ProtocolCodecFilter.filterWrite(ProtocolCodecFilter.java:313)
	at org.apache.mina.core.filterchain.DefaultIoFilterChain.callPreviousFilterWrite(DefaultIoFilterChain.java:506)
	at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1400(DefaultIoFilterChain.java:46)
	at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.filterWrite(DefaultIoFilterChain.java:805)
	at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.filterWrite(DefaultIoFilterChain.java:731)
	at org.apache.mina.core.filterchain.DefaultIoFilterChain.callPreviousFilterWrite(DefaultIoFilterChain.java:506)
	at org.apache.mina.core.filterchain.DefaultIoFilterChain.fireFilterWrite(DefaultIoFilterChain.java:498)
	at org.apache.mina.core.session.AbstractIoSession.write(AbstractIoSession.java:428)
	at org.apache.mina.core.session.AbstractIoSession.write(AbstractIoSession.java:369)
	at net.orfjackal.dimdwarf.net.SimpleSgsProtocolIoHandler.send(SimpleSgsProtocolIoHandler.scala:21)
	at net.orfjackal.dimdwarf.net.NetworkActor.process(NetworkActor.scala:49)
	at net.orfjackal.dimdwarf.actors.DeterministicMessageQueues.net$orfjackal$dimdwarf$actors$DeterministicMessageQueues$$processIfNonEmpty(DeterministicMessageQueues.scala:53)
	at net.orfjackal.dimdwarf.actors.DeterministicMessageQueues$$anonfun$processMessagesUntilIdle$1.apply(DeterministicMessageQueues.scala:41)
	at net.orfjackal.dimdwarf.actors.DeterministicMessageQueues$$anonfun$processMessagesUntilIdle$1.apply(DeterministicMessageQueues.scala:40)
	at scala.collection.immutable.Map$Map2.foreach(Map.scala:127)
	at net.orfjackal.dimdwarf.actors.DeterministicMessageQueues.processMessagesUntilIdle(DeterministicMessageQueues.scala:40)
	at net.orfjackal.dimdwarf.net.NetworkSpec$$anonfun$4.apply$mcV$sp(NetworkSpec.scala:87)
	at net.orfjackal.specsy.core.Context.net$orfjackal$specsy$core$Context$$executeSafely(Context.scala:65)
	at net.orfjackal.specsy.core.Context.execute(Context.scala:57)
	at net.orfjackal.specsy.core.Context.processSpec(Context.scala:46)
	at net.orfjackal.specsy.core.Context.specify(Context.scala:36)
	at net.orfjackal.specsy.Spec$NestedSpec.$greater$greater(Spec.scala:16)
	at net.orfjackal.dimdwarf.net.NetworkSpec.<init>(NetworkSpec.scala:78)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
	at net.orfjackal.specsy.core.SpecClassRunner$$anonfun$run$1$$anonfun$apply$1.apply$mcV$sp(SpecClassRunner.scala:14)
	at net.orfjackal.specsy.core.Context.net$orfjackal$specsy$core$Context$$executeSafely(Context.scala:65)
	at net.orfjackal.specsy.core.Context.execute(Context.scala:57)
	at net.orfjackal.specsy.core.Context.processSpec(Context.scala:46)
	at net.orfjackal.specsy.core.Context.bootstrap(Context.scala:22)
	at net.orfjackal.specsy.core.SpecClassRunner$$anonfun$run$1.apply(SpecClassRunner.scala:11)
	at net.orfjackal.specsy.core.SpecClassRunner$$anonfun$run$1.apply(SpecClassRunner.scala:9)
	at net.orfjackal.specsy.core.SpecRun.executeSafely(SpecRun.scala:23)
	at net.orfjackal.specsy.core.SpecRun.executePath(SpecRun.scala:17)
	at net.orfjackal.specsy.core.SpecRun.run(SpecRun.scala:9)
	at net.orfjackal.specsy.runner.SuiteRunner.await(SuiteRunner.scala:15)
	at net.orfjackal.specsy.junit.SpecsyJUnitRunner.runSpecs(SpecsyJUnitRunner.scala:28)
	at net.orfjackal.specsy.junit.SpecsyJUnitRunner.results(SpecsyJUnitRunner.scala:10)
	at net.orfjackal.specsy.junit.SpecsyJUnitRunner.net$orfjackal$specsy$junit$SpecsyJUnitRunner$$converter(SpecsyJUnitRunner.scala:11)
	at net.orfjackal.specsy.junit.SpecsyJUnitRunner.getDescription(SpecsyJUnitRunner.scala:65)
	at org.junit.runners.Suite.describeChild(Suite.java:123)
	at org.junit.runners.Suite.describeChild(Suite.java:24)
	at org.junit.runners.ParentRunner$4.compare(ParentRunner.java:305)
	at java.util.Arrays.mergeSort(Arrays.java:1270)
	at java.util.Arrays.sort(Arrays.java:1210)
	at java.util.Collections.sort(Collections.java:159)
	at org.junit.runners.ParentRunner.getFilteredChildren(ParentRunner.java:285)
	at org.junit.runners.ParentRunner.getDescription(ParentRunner.java:225)
	at org.junit.runners.Suite.describeChild(Suite.java:123)
	at org.junit.runners.Suite.describeChild(Suite.java:24)
	at org.junit.runners.ParentRunner$4.compare(ParentRunner.java:305)
	at java.util.Arrays.mergeSort(Arrays.java:1270)
	at java.util.Arrays.mergeSort(Arrays.java:1281)
	at java.util.Arrays.mergeSort(Arrays.java:1282)
	at java.util.Arrays.mergeSort(Arrays.java:1282)
	at java.util.Arrays.sort(Arrays.java:1210)
	at java.util.Collections.sort(Collections.java:159)
	at org.junit.runners.ParentRunner.getFilteredChildren(ParentRunner.java:285)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at com.intellij.junit4.IdeaSuite.getDescription(IdeaSuite.java:46)
	at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:65)
	at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:192)
	at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:64)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at com.intellij.rt.execution.application.AppMain.main(AppMain.java:115)
Caused by: scala.MatchError: LogoutSuccess()
	at net.orfjackal.dimdwarf.net.SimpleSgsProtocolEncoder.encode(SimpleSgsProtocolEncoder.scala:12)
	at org.apache.mina.filter.codec.ProtocolCodecFilter.filterWrite(ProtocolCodecFilter.java:298)
	... 72 more
23.2.2011 23:25:29 org.apache.mina.core.service.IoHandlerAdapter exceptionCaught
WARNING: EXCEPTION, please implement net.orfjackal.dimdwarf.net.SimpleSgsProtocolIoHandler.exceptionCaught() for proper handling:
org.apache.mina.filter.codec.ProtocolEncoderException: scala.MatchError: LogoutSuccess()
	at org.apache.mina.filter.codec.ProtocolCodecFilter.filterWrite(ProtocolCodecFilter.java:313)
	at org.apache.mina.core.filterchain.DefaultIoFilterChain.callPreviousFilterWrite(DefaultIoFilterChain.java:506)
	at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1400(DefaultIoFilterChain.java:46)
	at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.filterWrite(DefaultIoFilterChain.java:805)
	at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.filterWrite(DefaultIoFilterChain.java:731)
	at org.apache.mina.core.filterchain.DefaultIoFilterChain.callPreviousFilterWrite(DefaultIoFilterChain.java:506)
	at org.apache.mina.core.filterchain.DefaultIoFilterChain.fireFilterWrite(DefaultIoFilterChain.java:498)
	at org.apache.mina.core.session.AbstractIoSession.write(AbstractIoSession.java:428)
	at org.apache.mina.core.session.AbstractIoSession.write(AbstractIoSession.java:369)
	at net.orfjackal.dimdwarf.net.SimpleSgsProtocolIoHandler.send(SimpleSgsProtocolIoHandler.scala:21)
	at net.orfjackal.dimdwarf.net.NetworkActor.process(NetworkActor.scala:49)
	at net.orfjackal.dimdwarf.actors.DeterministicMessageQueues.net$orfjackal$dimdwarf$actors$DeterministicMessageQueues$$processIfNonEmpty(DeterministicMessageQueues.scala:53)
	at net.orfjackal.dimdwarf.actors.DeterministicMessageQueues$$anonfun$processMessagesUntilIdle$1.apply(DeterministicMessageQueues.scala:41)
	at net.orfjackal.dimdwarf.actors.DeterministicMessageQueues$$anonfun$processMessagesUntilIdle$1.apply(DeterministicMessageQueues.scala:40)
	at scala.collection.immutable.Map$Map2.foreach(Map.scala:127)
	at net.orfjackal.dimdwarf.actors.DeterministicMessageQueues.processMessagesUntilIdle(DeterministicMessageQueues.scala:40)
	at net.orfjackal.dimdwarf.net.NetworkSpec$$anonfun$4.apply$mcV$sp(NetworkSpec.scala:87)
	at net.orfjackal.specsy.core.Context.net$orfjackal$specsy$core$Context$$executeSafely(Context.scala:65)
	at net.orfjackal.specsy.core.Context.execute(Context.scala:57)
	at net.orfjackal.specsy.core.Context.processSpec(Context.scala:46)
	at net.orfjackal.specsy.core.Context.specify(Context.scala:36)
	at net.orfjackal.specsy.Spec$NestedSpec.$greater$greater(Spec.scala:16)
	at net.orfjackal.dimdwarf.net.NetworkSpec.<init>(NetworkSpec.scala:78)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
	at net.orfjackal.specsy.core.SpecClassRunner$$anonfun$run$1$$anonfun$apply$1.apply$mcV$sp(SpecClassRunner.scala:14)
	at net.orfjackal.specsy.core.Context.net$orfjackal$specsy$core$Context$$executeSafely(Context.scala:65)
	at net.orfjackal.specsy.core.Context.execute(Context.scala:57)
	at net.orfjackal.specsy.core.Context.processSpec(Context.scala:46)
	at net.orfjackal.specsy.core.Context.bootstrap(Context.scala:22)
	at net.orfjackal.specsy.core.SpecClassRunner$$anonfun$run$1.apply(SpecClassRunner.scala:11)
	at net.orfjackal.specsy.core.SpecClassRunner$$anonfun$run$1.apply(SpecClassRunner.scala:9)
	at net.orfjackal.specsy.core.SpecRun.executeSafely(SpecRun.scala:23)
	at net.orfjackal.specsy.core.SpecRun.executePath(SpecRun.scala:17)
	at net.orfjackal.specsy.core.SpecRun.run(SpecRun.scala:9)
	at net.orfjackal.specsy.runner.SuiteRunner.await(SuiteRunner.scala:15)
	at net.orfjackal.specsy.junit.SpecsyJUnitRunner.runSpecs(SpecsyJUnitRunner.scala:28)
	at net.orfjackal.specsy.junit.SpecsyJUnitRunner.results(SpecsyJUnitRunner.scala:10)
	at net.orfjackal.specsy.junit.SpecsyJUnitRunner.net$orfjackal$specsy$junit$SpecsyJUnitRunner$$converter(SpecsyJUnitRunner.scala:11)
	at net.orfjackal.specsy.junit.SpecsyJUnitRunner.getDescription(SpecsyJUnitRunner.scala:65)
	at org.junit.runners.Suite.describeChild(Suite.java:123)
	at org.junit.runners.Suite.describeChild(Suite.java:24)
	at org.junit.runners.ParentRunner$4.compare(ParentRunner.java:305)
	at java.util.Arrays.mergeSort(Arrays.java:1270)
	at java.util.Arrays.sort(Arrays.java:1210)
	at java.util.Collections.sort(Collections.java:159)
	at org.junit.runners.ParentRunner.getFilteredChildren(ParentRunner.java:285)
	at org.junit.runners.ParentRunner.getDescription(ParentRunner.java:225)
	at org.junit.runners.Suite.describeChild(Suite.java:123)
	at org.junit.runners.Suite.describeChild(Suite.java:24)
	at org.junit.runners.ParentRunner$4.compare(ParentRunner.java:305)
	at java.util.Arrays.mergeSort(Arrays.java:1270)
	at java.util.Arrays.mergeSort(Arrays.java:1281)
	at java.util.Arrays.mergeSort(Arrays.java:1282)
	at java.util.Arrays.mergeSort(Arrays.java:1282)
	at java.util.Arrays.sort(Arrays.java:1210)
	at java.util.Collections.sort(Collections.java:159)
	at org.junit.runners.ParentRunner.getFilteredChildren(ParentRunner.java:285)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at com.intellij.junit4.IdeaSuite.getDescription(IdeaSuite.java:46)
	at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:65)
	at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:192)
	at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:64)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at com.intellij.rt.execution.application.AppMain.main(AppMain.java:115)
Caused by: scala.MatchError: LogoutSuccess()
	at net.orfjackal.dimdwarf.net.SimpleSgsProtocolEncoder.encode(SimpleSgsProtocolEncoder.scala:12)
	at org.apache.mina.filter.codec.ProtocolCodecFilter.filterWrite(ProtocolCodecFilter.java:298)
	... 72 more

Thread dump during freeze (excluding unrelated threads)

2011-02-23 23:27:10
Full thread dump Java HotSpot(TM) 64-Bit Server VM (17.1-b03 mixed mode):

"NioProcessor-26" prio=6 tid=0x000000003f97b800 nid=0x1a5c runnable [0x000000004281f000]
   java.lang.Thread.State: RUNNABLE
	at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method)
	at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:273)
	at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:255)
	at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:136)
	at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
	- locked <0x000000002ba8ebd0> (a sun.nio.ch.Util$1)
	- locked <0x000000002ba8ebb8> (a java.util.Collections$UnmodifiableSet)
	- locked <0x000000002ba8e810> (a sun.nio.ch.WindowsSelectorImpl)
	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
	at org.apache.mina.transport.socket.nio.NioProcessor.select(NioProcessor.java:69)
	at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:961)
	at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:662)

"NioSocketAcceptor-6" prio=6 tid=0x000000003f97b000 nid=0x199c runnable [0x000000004271f000]
   java.lang.Thread.State: RUNNABLE
	at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method)
	at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:273)
	at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:255)
	at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:136)
	at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
	- locked <0x000000002baa6f98> (a sun.nio.ch.Util$1)
	- locked <0x000000002baa6f80> (a java.util.Collections$UnmodifiableSet)
	- locked <0x000000002baa6bd8> (a sun.nio.ch.WindowsSelectorImpl)
	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:84)
	at org.apache.mina.transport.socket.nio.NioSocketAcceptor.select(NioSocketAcceptor.java:288)
	at org.apache.mina.core.polling.AbstractPollingIoAcceptor$Acceptor.run(AbstractPollingIoAcceptor.java:402)
	at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:662)

"main" prio=6 tid=0x00000000006fe800 nid=0xbb0 runnable [0x00000000026ec000]
   java.lang.Thread.State: RUNNABLE
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.read(SocketInputStream.java:129)
	at java.net.SocketInputStream.read(SocketInputStream.java:182)
	at java.io.DataInputStream.readUnsignedShort(DataInputStream.java:320)
	at net.orfjackal.dimdwarf.net.SimpleSgsProtocolReferenceMessages$.nextMessage(SimpleSgsProtocolReferenceMessages.scala:11)
	at net.orfjackal.dimdwarf.net.NetworkSpec$$anonfun$4$$anonfun$apply$mcV$sp$11.apply$mcV$sp(NetworkSpec.scala:99)
	at net.orfjackal.specsy.core.Context.net$orfjackal$specsy$core$Context$$executeSafely(Context.scala:65)
	at net.orfjackal.specsy.core.Context.execute(Context.scala:57)
	at net.orfjackal.specsy.core.Context.processSpec(Context.scala:46)
	at net.orfjackal.specsy.core.Context.specify(Context.scala:36)
	at net.orfjackal.specsy.Spec$NestedSpec.$greater$greater(Spec.scala:16)
	at net.orfjackal.dimdwarf.net.NetworkSpec$$anonfun$4.apply$mcV$sp(NetworkSpec.scala:98)
	at net.orfjackal.specsy.core.Context.net$orfjackal$specsy$core$Context$$executeSafely(Context.scala:65)
	at net.orfjackal.specsy.core.Context.execute(Context.scala:57)
	at net.orfjackal.specsy.core.Context.processSpec(Context.scala:46)
	at net.orfjackal.specsy.core.Context.specify(Context.scala:36)
	at net.orfjackal.specsy.Spec$NestedSpec.$greater$greater(Spec.scala:16)
	at net.orfjackal.dimdwarf.net.NetworkSpec.<init>(NetworkSpec.scala:78)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
	at net.orfjackal.specsy.core.SpecClassRunner$$anonfun$run$1$$anonfun$apply$1.apply$mcV$sp(SpecClassRunner.scala:14)
	at net.orfjackal.specsy.core.Context.net$orfjackal$specsy$core$Context$$executeSafely(Context.scala:65)
	at net.orfjackal.specsy.core.Context.execute(Context.scala:57)
	at net.orfjackal.specsy.core.Context.processSpec(Context.scala:46)
	at net.orfjackal.specsy.core.Context.bootstrap(Context.scala:22)
	at net.orfjackal.specsy.core.SpecClassRunner$$anonfun$run$1.apply(SpecClassRunner.scala:11)
	at net.orfjackal.specsy.core.SpecClassRunner$$anonfun$run$1.apply(SpecClassRunner.scala:9)
	at net.orfjackal.specsy.core.SpecRun.executeSafely(SpecRun.scala:23)
	at net.orfjackal.specsy.core.SpecRun.executePath(SpecRun.scala:17)
	at net.orfjackal.specsy.core.SpecRun.run(SpecRun.scala:9)
	at net.orfjackal.specsy.runner.SuiteRunner.await(SuiteRunner.scala:15)
	at net.orfjackal.specsy.junit.SpecsyJUnitRunner.runSpecs(SpecsyJUnitRunner.scala:28)
	at net.orfjackal.specsy.junit.SpecsyJUnitRunner.results(SpecsyJUnitRunner.scala:10)
	- locked <0x000000002dd6c360> (a net.orfjackal.specsy.Specsy)
	at net.orfjackal.specsy.junit.SpecsyJUnitRunner.net$orfjackal$specsy$junit$SpecsyJUnitRunner$$converter(SpecsyJUnitRunner.scala:11)
	- locked <0x000000002dd6c360> (a net.orfjackal.specsy.Specsy)
	at net.orfjackal.specsy.junit.SpecsyJUnitRunner.getDescription(SpecsyJUnitRunner.scala:65)
	at org.junit.runners.Suite.describeChild(Suite.java:123)
	at org.junit.runners.Suite.describeChild(Suite.java:24)
	at org.junit.runners.ParentRunner$4.compare(ParentRunner.java:305)
	at java.util.Arrays.mergeSort(Arrays.java:1270)
	at java.util.Arrays.sort(Arrays.java:1210)
	at java.util.Collections.sort(Collections.java:159)
	at org.junit.runners.ParentRunner.getFilteredChildren(ParentRunner.java:285)
	at org.junit.runners.ParentRunner.getDescription(ParentRunner.java:225)
	at org.junit.runners.Suite.describeChild(Suite.java:123)
	at org.junit.runners.Suite.describeChild(Suite.java:24)
	at org.junit.runners.ParentRunner$4.compare(ParentRunner.java:305)
	at java.util.Arrays.mergeSort(Arrays.java:1270)
	at java.util.Arrays.mergeSort(Arrays.java:1281)
	at java.util.Arrays.mergeSort(Arrays.java:1282)
	at java.util.Arrays.mergeSort(Arrays.java:1282)
	at java.util.Arrays.sort(Arrays.java:1210)
	at java.util.Collections.sort(Collections.java:159)
	at org.junit.runners.ParentRunner.getFilteredChildren(ParentRunner.java:285)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at com.intellij.junit4.IdeaSuite.getDescription(IdeaSuite.java:46)
	at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:65)
	at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:192)
	at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:64)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at com.intellij.rt.execution.application.AppMain.main(AppMain.java:115)

JNI global references: 1277

Heap
 PSYoungGen      total 52416K, used 22413K [0x000000002acb0000, 0x00000000312f0000, 0x000000003acb0000)
  eden space 49088K, 40% used [0x000000002acb0000,0x000000002c04db88,0x000000002dca0000)
  from space 3328K, 69% used [0x000000002dca0000,0x000000002dee5bb0,0x000000002dfe0000)
  to   space 3264K, 0% used [0x0000000030fc0000,0x0000000030fc0000,0x00000000312f0000)
 PSOldGen        total 32768K, used 2561K [0x000000000acb0000, 0x000000000ccb0000, 0x000000002acb0000)
  object space 32768K, 7% used [0x000000000acb0000,0x000000000af30620,0x000000000ccb0000)
 PSPermGen       total 23168K, used 23118K [0x00000000058b0000, 0x0000000006f50000, 0x000000000acb0000)
  object space 23168K, 99% used [0x00000000058b0000,0x0000000006f43aa0,0x0000000006f50000)

Step 2

• Commit
• step2-stderr_bg-thread-exception.txt

Changed code to fix the exception in the background thread

SimpleSgsProtocolEncoder.scala @ 294f64e

                 put(SimpleSgsProtocol.LOGIN_FAILURE).
                 putShort(0.asInstanceOf[Short]).
                 flip()
+
+      case LogoutSuccess() =>
     }
     out.write(encoded)
   }

Run tests: the test freezes, a different stack trace is printed

Console output

23.2.2011 23:39:28 net.orfjackal.dimdwarf.net.NetworkActor start
INFO: Begin listening on port 52311
23.2.2011 23:39:28 org.apache.mina.filter.logging.LoggingFilter log
WARNING: EXCEPTION :
java.lang.IllegalStateException: Don't know how to handle message of type 'scala.runtime.BoxedUnit'.  Are you missing a protocol encoder?
	at org.apache.mina.core.polling.AbstractPollingIoProcessor.flushNow(AbstractPollingIoProcessor.java:789)
	at org.apache.mina.core.polling.AbstractPollingIoProcessor.flush(AbstractPollingIoProcessor.java:692)
	at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$500(AbstractPollingIoProcessor.java:61)
	at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:973)
	at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:662)
23.2.2011 23:39:28 org.apache.mina.core.service.IoHandlerAdapter exceptionCaught
WARNING: EXCEPTION, please implement net.orfjackal.dimdwarf.net.SimpleSgsProtocolIoHandler.exceptionCaught() for proper handling:
java.lang.IllegalStateException: Don't know how to handle message of type 'scala.runtime.BoxedUnit'.  Are you missing a protocol encoder?
	at org.apache.mina.core.polling.AbstractPollingIoProcessor.flushNow(AbstractPollingIoProcessor.java:789)
	at org.apache.mina.core.polling.AbstractPollingIoProcessor.flush(AbstractPollingIoProcessor.java:692)
	at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$500(AbstractPollingIoProcessor.java:61)
	at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:973)
	at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:662)

Step 3

• Commit
• step3-thread-dump.txt

TODO

Step 4

• Commit
• step4-stderr_bg-thread-exception.txt
• step4-thread-dump.txt

TODO

Step 5

• Commit
• step5-exception.txt

TODO

Step 6

• Commit
• step6-stdout_ClientConnectionTest.login_and_logout_successfully.txt

TODO