PeekPokeAPI expectations don't return the actual test line (or I'm getting it very wrong) #4128
Description
Hi all! I'm using ChiselSim with Chisel 6.4.0. The actual tests test fine, but when an expectation fails, I sometimes find it hard to debug, except by adding loads of additional message arguments. For a concrete example:
it should "transmit a command packet" in {
simulate(new SPI) { c =>
c.reset.poke(true.B)
c.clock.step()
c.reset.poke(false.B)
c.clock.step()
c.io.req.ready.expect(true.B)
c.io.req.bits.cmd.poke(0x19.U)
c.io.req.bits.cmdRem.poke(0.U)
c.io.req.bits.respLen.poke(0.U)
c.io.req.valid.poke(true.B)
c.clock.step()
c.io.req.ready.expect(false.B)
}
}I haven't actually implemented any non-initial state yet, so I expect the final line to fail. And it does, but the spec file itself only gets a mention for the line with the simulate call (line 17 in this case). The full output is long, so it's hidden below.
`sbt test` output with `-oF` added to the test options
sbt:ili9341spi> test
[info] SPISpec:
[info] SPI
[info] - should transmit a command packet *** FAILED ***
[info] chisel3.simulator.PeekPokeAPI$FailedExpectationException: Failed Expectation: Observed value '1' != 0. Expectation failed: observed value 1 != 0
[info] at chisel3.simulator.PeekPokeAPI$testableData.$anonfun$expect$9(PeekPokeAPI.scala:135)
[info] at chisel3.simulator.PeekPokeAPI$testableData.$anonfun$expect$9$adapted(PeekPokeAPI.scala:133)
[info] at svsim.Simulation$Port$$anonfun$check$1.applyOrElse(Simulation.scala:426)
[info] at svsim.Simulation$Port$$anonfun$check$1.applyOrElse(Simulation.scala:424)
[info] at scala.runtime.AbstractPartialFunction.apply(AbstractPartialFunction.scala:35)
[info] at svsim.Simulation$Controller.$anonfun$completeInFlightCommands$1(Simulation.scala:195)
[info] at svsim.Simulation$Controller.$anonfun$completeInFlightCommands$1$adapted(Simulation.scala:192)
[info] at scala.collection.IterableOnceOps.foreach(IterableOnce.scala:576)
[info] at scala.collection.IterableOnceOps.foreach$(IterableOnce.scala:574)
[info] at scala.collection.AbstractIterable.foreach(Iterable.scala:933)
[info] at svsim.Simulation$Controller.completeInFlightCommands(Simulation.scala:192)
[info] at chisel3.simulator.package$AnySimulatedModule.completeSimulation(package.scala:56)
[info] at chisel3.simulator.Simulator.$anonfun$_simulate$1(Simulator.scala:112)
[info] at chisel3.simulator.package$ChiselSimulation.$anonfun$runElaboratedModule$2(package.scala:97)
[info] at scala.util.DynamicVariable.withValue(DynamicVariable.scala:59)
[info] at chisel3.simulator.package$AnySimulatedModule$.withValue(package.scala:81)
[info] at chisel3.simulator.package$ChiselSimulation.$anonfun$runElaboratedModule$1(package.scala:97)
[info] at svsim.Simulation.$anonfun$run$3(Simulation.scala:51)
[info] at scala.util.Try$.apply(Try.scala:210)
[info] at svsim.Simulation.run(Simulation.scala:50)
[info] at chisel3.simulator.package$ChiselSimulation.runElaboratedModule(package.scala:94)
[info] at chisel3.simulator.Simulator$WorkspaceCompiler.$anonfun$process$1(Simulator.scala:64)
[info] at scala.util.Try$.apply(Try.scala:210)
[info] at chisel3.simulator.Simulator$WorkspaceCompiler.liftedTree1$1(Simulator.scala:64)
[info] at chisel3.simulator.Simulator$WorkspaceCompiler.process(Simulator.scala:53)
[info] at chisel3.simulator.SingleBackendSimulator.processBackends(Simulator.scala:139)
[info] at chisel3.simulator.SingleBackendSimulator.processBackends$(Simulator.scala:138)
[info] at chisel3.simulator.EphemeralSimulator$DefaultSimulator.processBackends(EphemeralSimulator.scala:28)
[info] at chisel3.simulator.Simulator._simulate(Simulator.scala:116)
[info] at chisel3.simulator.Simulator._simulate$(Simulator.scala:97)
[info] at chisel3.simulator.EphemeralSimulator$DefaultSimulator._simulate(EphemeralSimulator.scala:28)
[info] at chisel3.simulator.SingleBackendSimulator.simulate(Simulator.scala:146)
[info] at chisel3.simulator.SingleBackendSimulator.simulate$(Simulator.scala:142)
[info] at chisel3.simulator.EphemeralSimulator$DefaultSimulator.simulate(EphemeralSimulator.scala:28)
[info] at chisel3.simulator.EphemeralSimulator$.simulate(EphemeralSimulator.scala:25)
[info] at ee.kivikakk.ili9341spi.spi.SPISpec.$anonfun$new$1(SPISpec.scala:17)
[info] at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.scala:18)
[info] at org.scalatest.OutcomeOf.outcomeOf(OutcomeOf.scala:85)
[info] at org.scalatest.OutcomeOf.outcomeOf$(OutcomeOf.scala:83)
[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.flatspec.AnyFlatSpecLike$$anon$5.apply(AnyFlatSpecLike.scala:1832)
[info] at org.scalatest.TestSuite.withFixture(TestSuite.scala:196)
[info] at org.scalatest.TestSuite.withFixture$(TestSuite.scala:195)
[info] at org.scalatest.flatspec.AnyFlatSpec.withFixture(AnyFlatSpec.scala:1686)
[info] at org.scalatest.flatspec.AnyFlatSpecLike.invokeWithFixture$1(AnyFlatSpecLike.scala:1830)
[info] at org.scalatest.flatspec.AnyFlatSpecLike.$anonfun$runTest$1(AnyFlatSpecLike.scala:1842)
[info] at org.scalatest.SuperEngine.runTestImpl(Engine.scala:306)
[info] at org.scalatest.flatspec.AnyFlatSpecLike.runTest(AnyFlatSpecLike.scala:1842)
[info] at org.scalatest.flatspec.AnyFlatSpecLike.runTest$(AnyFlatSpecLike.scala:1824)
[info] at org.scalatest.flatspec.AnyFlatSpec.runTest(AnyFlatSpec.scala:1686)
[info] at org.scalatest.flatspec.AnyFlatSpecLike.$anonfun$runTests$1(AnyFlatSpecLike.scala:1900)
[info] at org.scalatest.SuperEngine.$anonfun$runTestsInBranch$1(Engine.scala:413)
[info] at scala.collection.immutable.List.foreach(List.scala:333)
[info] at org.scalatest.SuperEngine.traverseSubNodes$1(Engine.scala:401)
[info] at org.scalatest.SuperEngine.runTestsInBranch(Engine.scala:390)
[info] at org.scalatest.SuperEngine.$anonfun$runTestsInBranch$1(Engine.scala:427)
[info] at scala.collection.immutable.List.foreach(List.scala:333)
[info] at org.scalatest.SuperEngine.traverseSubNodes$1(Engine.scala:401)
[info] at org.scalatest.SuperEngine.runTestsInBranch(Engine.scala:396)
[info] at org.scalatest.SuperEngine.runTestsImpl(Engine.scala:475)
[info] at org.scalatest.flatspec.AnyFlatSpecLike.runTests(AnyFlatSpecLike.scala:1900)
[info] at org.scalatest.flatspec.AnyFlatSpecLike.runTests$(AnyFlatSpecLike.scala:1899)
[info] at org.scalatest.flatspec.AnyFlatSpec.runTests(AnyFlatSpec.scala:1686)
[info] at org.scalatest.Suite.run(Suite.scala:1114)
[info] at org.scalatest.Suite.run$(Suite.scala:1096)
[info] at org.scalatest.flatspec.AnyFlatSpec.org$scalatest$flatspec$AnyFlatSpecLike$$super$run(AnyFlatSpec.scala:1686)
[info] at org.scalatest.flatspec.AnyFlatSpecLike.$anonfun$run$1(AnyFlatSpecLike.scala:1945)
[info] at org.scalatest.SuperEngine.runImpl(Engine.scala:535)
[info] at org.scalatest.flatspec.AnyFlatSpecLike.run(AnyFlatSpecLike.scala:1945)
[info] at org.scalatest.flatspec.AnyFlatSpecLike.run$(AnyFlatSpecLike.scala:1943)
[info] at org.scalatest.flatspec.AnyFlatSpec.run(AnyFlatSpec.scala:1686)
[info] at org.scalatest.tools.Framework.org$scalatest$tools$Framework$$runSuite(Framework.scala:321)
[info] at org.scalatest.tools.Framework$ScalaTestTask.execute(Framework.scala:517)
[info] at sbt.TestRunner.runTest$1(TestFramework.scala:153)
[info] at sbt.TestRunner.run(TestFramework.scala:168)
[info] at sbt.TestFramework$$anon$3$$anonfun$$lessinit$greater$1.$anonfun$apply$1(TestFramework.scala:336)
[info] at sbt.TestFramework$.sbt$TestFramework$$withContextLoader(TestFramework.scala:296)
[info] at sbt.TestFramework$$anon$3$$anonfun$$lessinit$greater$1.apply(TestFramework.scala:336)
[info] at sbt.TestFramework$$anon$3$$anonfun$$lessinit$greater$1.apply(TestFramework.scala:336)
[info] at sbt.TestFunction.apply(TestFramework.scala:348)
[info] at sbt.Tests$.$anonfun$toTask$1(Tests.scala:436)
[info] at sbt.std.Transform$$anon$3.$anonfun$apply$2(Transform.scala:47)
[info] at sbt.std.Transform$$anon$4.work(Transform.scala:69)
[info] at sbt.Execute.$anonfun$submit$2(Execute.scala:283)
[info] at sbt.internal.util.ErrorHandling$.wideConvert(ErrorHandling.scala:24)
[info] at sbt.Execute.work(Execute.scala:292)
[info] at sbt.Execute.$anonfun$submit$1(Execute.scala:283)
[info] at sbt.ConcurrentRestrictions$$anon$4.$anonfun$submitValid$1(ConcurrentRestrictions.scala:265)
[info] at sbt.CompletionService$$anon$2.call(CompletionService.scala:65)
[info] at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317)
[info] at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572)
[info] at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317)
[info] at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
[info] at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
[info] at java.base/java.lang.Thread.run(Thread.java:1583)
[info] Run completed in 3 seconds, 242 milliseconds.
[info] Total number of tests run: 1
[info] Suites: completed 1, aborted 0
[info] Tests: succeeded 0, failed 1, canceled 0, ignored 0, pending 0
[info] *** 1 TEST FAILED ***
[error] Failed tests:
[error] ee.kivikakk.ili9341spi.spi.SPISpec
[error] (Test / test) sbt.TestsFailedException: Tests unsuccessful
[error] Total time: 3 s, completed Jun 2, 2024, 4:12:17 PM
sbt:ili9341spi>sbt:ili9341spi> lastGrep SPISpec test
[debug] Running TaskDef(ee.kivikakk.ili9341spi.spi.SPISpec, org.scalatest.tools.Framework$$anon$1@309d642a, false, [SuiteSelector])
[info] SPISpec:
[info] at ee.kivikakk.ili9341spi.spi.SPISpec.$anonfun$new$1(SPISpec.scala:17)
[error] ee.kivikakk.ili9341spi.spi.SPISpec
sbt:ili9341spi>I'm sure this is hard to avoid because expect is probably just enqueuing the expectation until the sim runtime next goes back to talk to the simulator. (Or something — I haven't looked into how it works at all, other than seeing that such a flow is possible!)
I guess it'd be nice to also capture SourceInfo when doing an expect, and to report it with any failures? Any thoughts, or if I'm missing something big?