PeekPokeAPI expectations don't return the actual test line (or I'm getting it very wrong)

[kivikakk]

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?

[kivikakk]

I should add — I'm happy to have a go at the implementation if it is indeed as simple a matter as I imagine!

[jackkoenig]

Thanks for the report! Improving this would be really good for the user experience.

There are two ways we could fix it:

1. Grab a SourceInfo and leverage Chisel's error reporting mechanisms to report the error (can even include source line and carat for most cases)
2. Grab a stack trace and throw an exception pointing to the line

(1) probably the easiest and definitely the most performant, (2) grabbing stack traces for every single expect could be a bit expensive (more expensive than simulation? unclear, would need to be measured).

Thank you for your interest and having a go at the implementation. If you can get to it, great, if not, at least this will serve as a suggested implementation for anyone else who gets a chance to take a look.

You can capture a SourceInfo by adding it as an implicit argument to the method, in this case expect¹ (note that every overloaded method will need it). I think you just need then to use this SourceInfo in reporting the error where there is currently an exception thrown².

If you just want to report the source locator, that should be enough. If you want to make it a bit prettier with Chisel pulling the source-line and having a carat pointing to the offending expect, you can try using some of Chisel's error reporting logic in the ErrorLog³. You may need to massage the internal APIs a bit as they are very much built around the assumption of a Chisel runtime that reports errors at the end (which SVSim does not interact with at all). Not sure it's worth it for you to attempt that, but it's an option!

Footnotes

1. https://github.com/chipsalliance/chisel/blob/0f2efb52a78be5484fa231d5d635ce0a4b124bd8/src/main/scala/chisel3/simulator/PeekPokeAPI.scala#L59 ↩

2. https://github.com/chipsalliance/chisel/blob/0f2efb52a78be5484fa231d5d635ce0a4b124bd8/src/main/scala/chisel3/simulator/PeekPokeAPI.scala#L135 ↩

3. https://github.com/chipsalliance/chisel/blob/0f2efb52a78be5484fa231d5d635ce0a4b124bd8/core/src/main/scala/chisel3/internal/Error.scala#L251 ↩

[kivikakk]

Thank you so much for the pointers! I'll get (1) going as-is to have something minimal, and then I'll give the better reporting a try. If I have the time I'll see about (2); I can imagine it might indeed be expensive.

[jackkoenig]

The fix has been merged to main and backported to 6.x. I'm not sure when 6.5.0 will be released with this improvement but you can use a SNAPSHOT that includes it 6.4.0+3-26ae5a85-SNAPSHOT. You'll need to enable the resolver for SonatypeS01 Snapshots to use that, instructions vary by build tool:

• Scala-Cli: //> using repository "sonatype-s01:snapshots"
• SBT: resolvers += Resolver.sonatypeOssRepos("snapshots")

[kivikakk]

Ta! 😊