diff --git a/README.md b/README.md index 54801b6..29752a2 100644 --- a/README.md +++ b/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`). diff --git a/src/main/scala/io/stepfunc/dnp3c/conformance/common/UnconfirmedResponse.scala b/src/main/scala/io/stepfunc/dnp3c/conformance/common/UnconfirmedResponse.scala index 873f3e5..016a8bf 100644 --- a/src/main/scala/io/stepfunc/dnp3c/conformance/common/UnconfirmedResponse.scala +++ b/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) diff --git a/src/main/scala/io/stepfunc/dnp3c/conformance/common/UnsolicitedResponseSteps.scala b/src/main/scala/io/stepfunc/dnp3c/conformance/common/UnsolicitedResponseSteps.scala index c030789..b508382 100644 --- a/src/main/scala/io/stepfunc/dnp3c/conformance/common/UnsolicitedResponseSteps.scala +++ b/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 = diff --git a/src/main/scala/io/stepfunc/dnp3c/conformance/v27/Procedure8_11_2_1.scala b/src/main/scala/io/stepfunc/dnp3c/conformance/v27/Procedure8_11_2_1.scala index ffc2bf0..8b74f00 100644 --- a/src/main/scala/io/stepfunc/dnp3c/conformance/v27/Procedure8_11_2_1.scala +++ b/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 + } + } } diff --git a/src/main/scala/io/stepfunc/dnp3c/dnp3/DefaultTestDriver.scala b/src/main/scala/io/stepfunc/dnp3c/dnp3/DefaultTestDriver.scala index bbdfb90..fe32de6 100644 --- a/src/main/scala/io/stepfunc/dnp3c/dnp3/DefaultTestDriver.scala +++ b/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) diff --git a/src/main/scala/io/stepfunc/dnp3c/dnp3/TestDriver.scala b/src/main/scala/io/stepfunc/dnp3c/dnp3/TestDriver.scala index 33ae977..0d1904a 100644 --- a/src/main/scala/io/stepfunc/dnp3c/dnp3/TestDriver.scala +++ b/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") diff --git a/src/test/scala/io/stepfunc/dnp3c/conformance/v27/Procedure8_11_2_1Test.scala b/src/test/scala/io/stepfunc/dnp3c/conformance/v27/Procedure8_11_2_1Test.scala index a4193bf..4d38504 100644 --- a/src/test/scala/io/stepfunc/dnp3c/conformance/v27/Procedure8_11_2_1Test.scala +++ b/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,17 +33,22 @@ 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( @@ -51,13 +56,23 @@ class Procedure8_11_2_1Test extends AnyFunSuite with Matchers { 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) + } }