8.11.2.1 and 8.11.2a: accept a READ answer deferred to the unsolicited confirm timeout

README.md

@@ -50,6 +50,8 @@ dnp3c resolves this the same way for every point type. A device without the poin
 
 A level 1 test of a device that can't read a type (8.13.2a and the like) runs only for a device that has the type; a device without it gets the test above instead.
 
+3.1 rev 1 is also of two minds about when a device answers a READ sent while its startup unsolicited response is unconfirmed (8.11.2a step 24; 2.7's 8.11.2.1 has the same text). Step 24, and 8.11.1's restart behavior, read as an answer within the usual response time. 8.11.1's rules for unsolicited and polled responses have the device defer a READ received while any unsolicited response awaits confirmation, until the confirmation arrives or its timeout expires, and so does IEEE 1815-2012 4.6.6 rule 16. TB2015-002a makes the intent plain: it rewrites rule 16 to say the READ is deferred for the startup response too, then answered, then the startup response sent again. dnp3c reads step 24 in that light, in both revisions: step 24 waits the response timeout plus the unsolicited confirm timeout, and an answer that comes well before that timeout passes with a warning that the standard has it deferred.
+
 ## Requirements
 
 Java 17 or newer.
@@ -81,7 +83,6 @@ The library jar, `io.stepfunc:dnp3c`, is published to Maven Central. See [Automa
 - **3.1r1's 8.10.2** (multi-drop support) runs over serial, with the DUT on a drop with other devices (`serial.otherDevices`). The tool checks what the DUT sends; whether it raised carrier or asserted RTS, and when, the plugin checks on the line, e.g. by asking the tester to read an oscilloscope.
 - **Report by exception** isn't verified: where a procedure requires a device whose class 0 response spans several link frames to also report by exception, the log notes it but the tool doesn't check it.
 - **8.11.2.5.8** covers a device that holds unsolicited responses until it has a minimum number of events, not one that holds them for a time.
-- **8.11.2.1 step 24** (3.1r1's 8.11.2a): the procedure expects a READ to be answered while the device's startup unsolicited response is still unconfirmed, while IEEE 1815-2012 (4.6.6, rule 16 of the outstation's unsolicited response rules) requires the device to defer it until the confirm. The tool follows the procedure, but waits for the answer for the response timeout plus 200 ms, so a device that defers it passes only if the unsolicited response's confirm times out before then.
 - **8.6.4:** 2.7's description of the desired behavior still has a binary output in local mode set LOCAL_FORCED. TB2017-001 replaced the tests, which the tool runs, but not that description: in local mode an output clears ONLINE and keeps its other flags.
 - **Counter events in 3.1r1** may be changes of a counter's flags alone (TB2017-003a). The default plugin's prompts for 8.17 ask for counts, so a device that reports only flag changes needs a plugin that generates and checks those instead.
 - **3.1r1's 6.6.2d** (No Inter-frame Gap) is for serial and UDP, and for TCP only where the device has more than one DNP3 address. dnp3c runs it over serial (`serial.enabled`), and over TCP only for such a device (`supports.multipleAddresses`).

src/main/scala/io/stepfunc/dnp3c/conformance/common/UnconfirmedResponse.scala

@@ -83,7 +83,8 @@ class UnconfirmedResponse(confirmTimeoutMs: Int) {
     }
   }
 
-  private def msUntilTimeout(driver: TestDriver): Int = (receivedAtMs + confirmTimeoutMs - driver.clock.nowMs()).toInt
+  // the time left until the response's confirm timeout expires, negative once it has
+  def msUntilTimeout(driver: TestDriver): Int = (receivedAtMs + confirmTimeoutMs - driver.clock.nowMs()).toInt
 
   // the margin before the confirm timeout that expectNoResponseBeforeTimeout checks no message arrives in
   private def margin: Int = math.min(timingToleranceMs, confirmTimeoutMs / 4)

src/main/scala/io/stepfunc/dnp3c/conformance/common/UnsolicitedResponseSteps.scala

@@ -20,7 +20,8 @@ object UnsolicitedResponseSteps {
 
   // how long the DUT can take to send an unsolicited response to new events: its hold-off time, and any wait for the
   // confirmation of an earlier response
-  private def eventsTimeoutMs(holdOffMs: Int, unsolConfirmTimeoutMs: Int): Int = holdOffMs + unsolConfirmTimeoutMs + 200
+  private def eventsTimeoutMs(holdOffMs: Int, unsolConfirmTimeoutMs: Int): Int =
+    holdOffMs + unsolConfirmTimeoutMs + TestDriver.readToleranceMs
 
   // no unsolicited response to new events: wait as long as the DUT could take to send one
   private[conformance] def expectNoEventsUnsolicited(holdOffMs: Int, unsolConfirmTimeoutMs: Int): TestStep =

src/main/scala/io/stepfunc/dnp3c/conformance/v27/Procedure8_11_2_1.scala

@@ -8,10 +8,11 @@ import io.stepfunc.dnp3c.conformance.api.options.{ LinkOptions, SupportOptions,
 import io.stepfunc.dnp3c.dnp3.link.FrameValidator
 import io.stepfunc.dnp3c.conformance.common.GenericSteps._
 import io.stepfunc.dnp3c.conformance.common.UnconfirmedResponse
+import io.stepfunc.dnp3c.conformance.common.UnconfirmedResponse.timingToleranceMs
 import io.stepfunc.dnp3c.conformance.common.UnsolicitedResponseSteps.expectNoEventsUnsolicited
 import io.stepfunc.dnp3c.conformance.common.Validations
 import io.stepfunc.dnp3c.dnp3.app._
-import io.stepfunc.dnp3c.dnp3.{ AutoConfirm, LinkOverride, Requests }
+import io.stepfunc.dnp3c.dnp3.{ AutoConfirm, Comment, DeferredCheck, LinkOverride, Requests, TestDriver }
 import io.stepfunc.dnp3c.protocol.parsing.UInt16LE
 
 object Procedure8_11_2_1 extends ProcedureDefinition {
@@ -50,15 +51,46 @@ object Procedure8_11_2_1 extends ProcedureDefinition {
       20 --> expectSingleResponse(Sequence.zero, Validations.isNull && Validations.without(IIN.DEVICE_RESTART)),
       (21 to 22) --> restartResponse.expectRetry(Validations.isNull && Validations.without(IIN.DEVICE_RESTART)),
       23 --> send(Requests.readClass0(Sequence.one)),
-      24 -->
-        // the procedure expects this READ answered while the startup unsolicited response is still unconfirmed
-        // (8.11.1.3), where 1815-2012 4.6.6 rule 16 requires it deferred until the confirm. The procedure is followed,
-        // but a deferred answer passes if it comes within the response timeout plus 200 ms (see issue #1)
-        expectAtLeastOneResponse(Sequence.one),
+      // the procedures pull both ways here (see the README): step 24 and 8.11.1's restart behavior read as an answer
+      // within the usual response time, while 8.11.1's unsolicited and polled responses, IEEE 1815-2012 4.6.6 rule 16
+      // and TB2015-002a have the DUT defer the READ until the confirmation or its timeout. So step 24 accepts either:
+      // an answer deferred to the startup response's confirm timeout, or one well before it, with a warning
+
+      24 --> expectDeferrableAnswer(responseTimeoutMs(options), unsolConfirmTimeoutMs, restartResponse),
       (25 to 26) --> restartResponse.expectRetry(Validations.isNull, AutoConfirm.Wrong),
       (27 to 28) --> restartResponse.expectRetry(Validations.isNull, AutoConfirm.Yes),
       29 --> PluginSteps.generateUnsolicitedEvents(),
       30 --> expectNoEventsUnsolicited(holdOffMs, unsolConfirmTimeoutMs)
     )
   }
+
+  // the answer to step 23's READ, which the DUT may defer until the unsolicited response is confirmed or its confirm
+  // timeout expires
+  private def expectDeferrableAnswer(
+      responseTimeoutMs: Int,
+      confirmTimeoutMs: Int,
+      unsolicitedResponse: UnconfirmedResponse): TestStep = new TestStep {
+    private val read = expectAtLeastOneResponse(Sequence.one)
+    private val timeoutMs = responseTimeoutMs + confirmTimeoutMs + TestDriver.readToleranceMs
+
+    override def description: List[Comment] =
+      s"The DUT may defer its response until the startup unsolicited response is confirmed or its confirm timeout " +
+        s"expires, so wait up to $timeoutMs ms for it (the response timeout, the unsolicited confirm timeout and " +
+        s"${TestDriver.readToleranceMs} ms)" :: read.description
+
+    override def run(driver: TestDriver): List[DeferredCheck] = {
+      driver.readAllResponses(Sequence.one, AutoConfirm.Yes, firstTimeoutMs = Some(timeoutMs))
+      val leftMs = unsolicitedResponse.msUntilTimeout(driver)
+      driver.reporter.info(
+        s"The answer to the READ arrived ${confirmTimeoutMs - leftMs} ms after the unconfirmed unsolicited response, " +
+          s"whose confirm timeout is $confirmTimeoutMs ms")
+      if (leftMs > timingToleranceMs) {
+        driver.reporter.warning(
+          "the DUT answered the READ while its startup unsolicited response was unconfirmed; IEEE 1815-2012 4.6.6 " +
+            "rule 16, as amended by TB2015-002a, has the answer deferred until the confirmation arrives or the " +
+            "confirm timeout expires")
+      }
+      Nil
+    }
+  }
 }

src/main/scala/io/stepfunc/dnp3c/dnp3/DefaultTestDriver.scala

@@ -48,9 +48,6 @@ class DefaultTestDriver(
     }
   }
 
-  // added to the configured response timeouts, for the time a response takes to arrive
-  private val readToleranceMs = 200
-
   private var connection: Option[Connection] = None
 
   private def getConnection[A](fun: Connection => A): A = connection match {
@@ -201,7 +198,8 @@ class DefaultTestDriver(
       validator: FrameValidator,
       linkOverride: LinkOverride,
       timeoutMs: Option[Int]): Option[Message] = getConnection { c =>
-    val timeout = timeoutMs.getOrElse((if (unsolicited.value) unsolTimeoutMs else appTimeoutMs) + readToleranceMs)
+    val timeout =
+      timeoutMs.getOrElse((if (unsolicited.value) unsolTimeoutMs else appTimeoutMs) + TestDriver.readToleranceMs)
     val message = c.messageReader.read(timeout, validator, linkOverride).map(Message.parse)
     message.foreach(reporter.receive)
     message.foreach(policies.check)

src/main/scala/io/stepfunc/dnp3c/dnp3/TestDriver.scala

@@ -202,13 +202,19 @@ trait TestDriver {
       linkOverride: LinkOverride = LinkOverride.default,
       timeoutMs: Option[Int] = None): Option[Message]
 
+  // reads the fragments of a response; the first may be given longer than the default timeout, e.g. where the DUT may
+  // defer its response
   def readAllResponses(
       seq: Sequence,
       autoConfirm: AutoConfirm,
-      validator: FrameValidator = FrameValidator.none): List[Message] = {
+      validator: FrameValidator = FrameValidator.none,
+      firstTimeoutMs: Option[Int] = None): List[Message] = {
 
     @tailrec
-    def recurse(list: List[Message], seq: Sequence): List[Message] = readMessage(Unsolicited.No, validator) match {
+    def recurse(list: List[Message], seq: Sequence): List[Message] = readMessage(
+      Unsolicited.No,
+      validator,
+      timeoutMs = if (list.isEmpty) firstTimeoutMs else None) match {
       case None => throw new Exception("Unable to read complete message within timeout")
       case Some(message) =>
         if (message.ctrl.con.value) autoConfirm.execute(message, this)
@@ -225,6 +231,9 @@ trait TestDriver {
 
 object TestDriver {
 
+  // added to the configured response timeouts, for the time a response takes to arrive
+  val readToleranceMs = 200
+
   // what every fragment of a solicited response must carry
   def checkSolicited(message: Message, seq: Sequence): Unit = {
     if (message.ctrl.uns.value) throw new Exception("Unexpected unsolicited response")

src/test/scala/io/stepfunc/dnp3c/conformance/v27/Procedure8_11_2_1Test.scala

@@ -5,7 +5,7 @@ package io.stepfunc.dnp3c.conformance.v27
 
 import io.stepfunc.dnp3c.conformance.Run
 import io.stepfunc.dnp3c.conformance.api.Options
-import io.stepfunc.dnp3c.conformance.api.options.UnsolicitedOptions
+import io.stepfunc.dnp3c.conformance.api.options.{ OutstationOptions, UnsolicitedOptions }
 import io.stepfunc.dnp3c.dnp3._
 import io.stepfunc.dnp3c.dnp3.app._
 import io.stepfunc.dnp3c.dnp3.link.FrameValidator
@@ -33,31 +33,46 @@ class Procedure8_11_2_1Test extends AnyFunSuite with Matchers {
 
   // A DUT that sends a null unsolicited response (with DEVICE_RESTART until it's cleared) one confirm timeout after
   // each read for one, except the `early`th, which it sends at once, and nothing once events are generated; it answers
-  // requests with null responses. Records the timeouts of the reads for unsolicited responses after the events.
-  private class Dut(plugin: Plugin, confirmTimeoutMs: Int, early: Option[Int] = None)
+  // requests with null responses, or, if it defers READs, a READ's once the confirm timeout of the unsolicited response
+  // before it expires, and then retries that response at once. Records the timeouts of the reads for unsolicited
+  // responses after the events.
+  private class Dut(plugin: Plugin, confirmTimeoutMs: Int, early: Option[Int] = None, defersReads: Boolean = false)
       extends RespondingDriver(StubDriver.reporter(plugin)) {
     private var restart = true
     private var sent = 0
+    private var readDeferred = false
+    private var retryDue = false
     val timeoutsAfterEvents = mutable.ListBuffer.empty[Option[Int]]
 
     override def writeMessage(message: Message, options: LinkOverride): Unit = message.function match {
       case AppFunction.confirm =>
       case function =>
         if (function == AppFunction.write) restart = false
+        if (function == AppFunction.read) readDeferred = defersReads
         enqueue(Message(Control.request(message.ctrl.seq), AppFunction.response, Some(iin), Nil))
     }
     override def readMessage(
         unsolicited: Unsolicited,
         validator: FrameValidator,
         linkOverride: LinkOverride,
         timeoutMs: Option[Int]): Option[Message] =
-      if (!unsolicited.value) super.readMessage(unsolicited, validator, linkOverride, timeoutMs)
-      else if (plugin.eventsGenerated) {
+      if (!unsolicited.value) {
+        if (readDeferred) {
+          readDeferred = false
+          // the unsolicited response before the READ was just read: its confirm timeout expires one from now
+          val waitMs = timeoutMs.getOrElse(defaultResponseTimeoutMs)
+          if (waitMs < confirmTimeoutMs) return timedOut(Some(waitMs))
+          clock.advance(confirmTimeoutMs)
+          retryDue = true
+        }
+        super.readMessage(unsolicited, validator, linkOverride, timeoutMs)
+      } else if (plugin.eventsGenerated) {
         timeoutsAfterEvents += timeoutMs
         timedOut(timeoutMs)
       } else {
         sent += 1
-        if (!early.contains(sent)) clock.advance(confirmTimeoutMs)
+        if (!early.contains(sent) && !retryDue) clock.advance(confirmTimeoutMs)
+        retryDue = false
         Some(
           Message(
             Control(First.Yes, Final.Yes, Confirm.Yes, Unsolicited.Yes, Sequence.zero),
@@ -69,6 +84,11 @@ class Procedure8_11_2_1Test extends AnyFunSuite with Matchers {
     private def iin: IIN = if (restart) IIN.DEVICE_RESTART else IIN.empty
   }
 
+  private val responseTimeoutMs = 2000
+
+  // a read's default timeout: the response timeout plus the driver's tolerance
+  private val defaultResponseTimeoutMs = responseTimeoutMs + TestDriver.readToleranceMs
+
   test("step 30 waits for an unsolicited response to the events as long as the DUT could take to send one") {
     val plugin = new Plugin
     val dut = new Dut(plugin, 5000)
@@ -87,4 +107,29 @@ class Procedure8_11_2_1Test extends AnyFunSuite with Matchers {
     // steps 15 to 18 (the 3rd and 4th responses), 21 (the 5th), 25 (the 6th) and 27 (the 7th)
     for (n <- 3 to 7) withClue(s"response $n")(passes(Some(n)) should equal(false))
   }
+
+  // a response timeout shorter than the unsolicited confirm timeout
+  private val timeouts = Map(
+    OutstationOptions.responseTimeout.id -> responseTimeoutMs.toString,
+    UnsolicitedOptions.unsolicitedConfirmTimeoutMs.id -> "5000")
+
+  test("step 24 accepts a READ answered once the startup response's confirm timeout expires") {
+    Run.passes(Procedure8_11_2_1, new Dut(new Plugin, 5000, defersReads = true), timeouts) should equal(true)
+  }
+
+  test("step 24 warns of a READ answered while the startup response is unconfirmed, and notes nothing") {
+    val dut = new Dut(new Plugin, 5000)
+    Run.passing(Procedure8_11_2_1, dut, timeouts)
+    dut.reporter.notes should equal(Nil)
+    dut.reporter.warnings should have size 1
+    dut.reporter.warnings.head should
+      include("answered the READ while its startup unsolicited response was unconfirmed")
+  }
+
+  test("step 24 neither warns of nor notes a READ answered once the startup response's confirm timeout expires") {
+    val dut = new Dut(new Plugin, 5000, defersReads = true)
+    Run.passing(Procedure8_11_2_1, dut, timeouts)
+    dut.reporter.notes should equal(Nil)
+    dut.reporter.warnings should equal(Nil)
+  }
 }