Make the timing tolerance an option: test.timingToleranceMs

CHANGELOG.md

@@ -6,6 +6,7 @@
 - **Serial and UDP**, as well as TCP, including 3.1 rev 1's network, multi-drop and collision avoidance tests.
 - **Exclusions:** leave a procedure out of a run with a reason, e.g. for a known gap in the device. The report shows it as not run, apart from skipped procedures, with its reason.
 - **Reports** say why each procedure was skipped, flag the procedures that pass with warnings, where the device should probably change something, and name the revision and subset level.
+- **Timing tolerance:** `test.timingToleranceMs` (500 ms by default) sets how far the times dnp3c measures may be off, e.g. for a busy machine or a slow network. It replaces two fixed allowances, of 500 ms for timed intervals and 200 ms past each timeout, so the steps that expect no message now wait 300 ms longer by default.
 - The runnable jar and the CLI zip list the licenses of the dependencies they bundle.
 
 ### Upgrading from 0.1.0

docs/manual-testing.md

@@ -45,6 +45,10 @@ Every command that reads the configuration checks the whole file first, and list
 
 `dnp3c -options` prints every option and its default without writing a file.
 
+### Timing
+
+The tests that time the DUT, e.g. its unsolicited retries in 8.11, measure on the machine running dnp3c, so a busy machine or a slow network can make the DUT look early or late. `test.timingToleranceMs` (500 ms by default) is how far off those measurements may be, both ways: how long past a timeout dnp3c waits for a message, and how far an interval it times may be from the one expected. Run the timing tests on a machine that isn't busy with other work. If one fails under load, rerun it before treating it as a device problem, or raise the tolerance. A larger tolerance only makes the steps that expect no message wait longer: a step that gets its message moves on as soon as it arrives.
+
 ## Choose the revision
 
 dnp3c can hold more than one revision of the certification procedure, and every command that uses procedures needs the one to use, given with `-rev`. Revisions number their procedures differently, so `-rev` decides what an id like 8.6.5.4 means. `dnp3c -revs` lists the revisions:

src/main/scala/io/stepfunc/dnp3c/conformance/api/options/TestOptions.scala

@@ -27,6 +27,18 @@ object TestOptions extends OptionGroup {
     None
   )
 
+  val timingToleranceMs: IntegerOption = OptionTypes.integer(
+    this,
+    "timingToleranceMs",
+    500,
+    "How far a time the harness measures may be off, in ms, both ways: how late a message may arrive past a timeout " +
+      "the harness waits on, and how far an interval it times may be from the one expected, e.g. an unsolicited " +
+      "retry from the confirm timeout. A larger value is more forgiving of a slow network or a busy machine, both " +
+      "early and late. For the serial line's own timing, see serial.timingToleranceMs",
+    Some(0),
+    None
+  )
+
   val exclude: ExclusionsOption = OptionTypes.exclusions(
     this,
     "exclude",
@@ -40,6 +52,7 @@ object TestOptions extends OptionGroup {
 
   def prefix: String = "test"
   def description: String = "Options for the test harness itself"
-  def options: List[TestOption] = List(outputDirectory, deviceUnderTest, manualActionWindowMs, exclude)
+  def options: List[TestOption] =
+    List(outputDirectory, deviceUnderTest, manualActionWindowMs, timingToleranceMs, exclude)
 
 }

src/main/scala/io/stepfunc/dnp3c/conformance/application/TestRunner.scala

@@ -51,6 +51,7 @@ private[application] object ProcedureEnvironment {
         options.get(LinkOptions.timeout),
         options.get(OutstationOptions.responseTimeout),
         options.get(UnsolicitedOptions.unsolicitedConfirmTimeoutMs),
+        options.get(TestOptions.timingToleranceMs),
         policies = policies
       )
   }

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

@@ -5,15 +5,14 @@ package io.stepfunc.dnp3c.conformance.common
 
 import io.stepfunc.dnp3c.conformance.api._
 import io.stepfunc.dnp3c.conformance.common.GenericSteps.validateUnsolicitedResponse
-import io.stepfunc.dnp3c.conformance.common.UnconfirmedResponse.timingToleranceMs
 import io.stepfunc.dnp3c.dnp3.app._
 import io.stepfunc.dnp3c.dnp3.{ ActionTiming, AutoConfirm, Comment, MessageValidation, Requests, TestDriver }
 import io.stepfunc.dnp3c.dnp3.DeferredCheck
 
 // A response left unconfirmed, to check that the DUT holds back what it would otherwise send (e.g. the answer to a
 // READ) until the response is confirmed or its confirm timeout expires. Timing is measured from when the response
 // was received, on the driver's clock.
-class UnconfirmedResponse(confirmTimeoutMs: Int) {
+class UnconfirmedResponse(confirmTimeoutMs: Int, timingToleranceMs: Int) {
   private var response: Option[Message] = None
   private var receivedAtMs = 0L
 
@@ -118,9 +117,3 @@ class UnconfirmedResponse(confirmTimeoutMs: Int) {
     }
   }
 }
-
-object UnconfirmedResponse {
-  // Timing tolerance, e.g. between the DUT sending and us receiving a response. Adopted from the measurement
-  // accuracy 8.11.2.1 allows for unsolicited retries.
-  private[conformance] val timingToleranceMs = 500
-}

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

@@ -4,7 +4,7 @@
 package io.stepfunc.dnp3c.conformance.common
 
 import io.stepfunc.dnp3c.conformance.api._
-import io.stepfunc.dnp3c.conformance.api.options.{ SupportOptions, UnsolicitedOptions }
+import io.stepfunc.dnp3c.conformance.api.options.{ SupportOptions, TestOptions, UnsolicitedOptions }
 import io.stepfunc.dnp3c.dnp3.link.FrameValidator
 import io.stepfunc.dnp3c.conformance.common.GenericSteps._
 import io.stepfunc.dnp3c.conformance.common.Validations._
@@ -20,22 +20,25 @@ 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 + TestDriver.readToleranceMs
+  private def eventsTimeoutMs(holdOffMs: Int, unsolConfirmTimeoutMs: Int, toleranceMs: Int): Int =
+    holdOffMs + unsolConfirmTimeoutMs + toleranceMs
 
   // 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 =
-    expectNoUnsolicitedResponse(Some(eventsTimeoutMs(holdOffMs, unsolConfirmTimeoutMs)))
+  private[conformance] def expectNoEventsUnsolicited(
+      holdOffMs: Int,
+      unsolConfirmTimeoutMs: Int,
+      toleranceMs: Int): TestStep =
+    expectNoUnsolicitedResponse(Some(eventsTimeoutMs(holdOffMs, unsolConfirmTimeoutMs, toleranceMs)))
 
-  private def expectEventsUnsolicited(holdOffMs: Int, unsolConfirmTimeoutMs: Int)(
+  private def expectEventsUnsolicited(holdOffMs: Int, unsolConfirmTimeoutMs: Int, toleranceMs: Int)(
       autoConfirm: AutoConfirm,
       validation: MessageValidation = MessageValidation.none): TestStep =
     expectUnsolicitedResponse(
       autoConfirm,
       FrameValidator.none,
       withEvents(validation),
       LinkOverride.default,
-      Some(eventsTimeoutMs(holdOffMs, unsolConfirmTimeoutMs)))
+      Some(eventsTimeoutMs(holdOffMs, unsolConfirmTimeoutMs, toleranceMs)))
 
   // a response to new events carries them: checks that compare it with other responses would otherwise pass on a
   // response without any
@@ -49,13 +52,17 @@ object UnsolicitedResponseSteps {
    * tester) is armed first and acts within actionWindowMs, so the harness is already reading when the DUT responds,
    * and times the response from when it actually arrives.
    */
-  private[common] def generateAndExpectEvents(holdOffMs: Int, unsolConfirmTimeoutMs: Int, actionWindowMs: Int)(
+  private[common] def generateAndExpectEvents(
+      holdOffMs: Int,
+      unsolConfirmTimeoutMs: Int,
+      toleranceMs: Int,
+      actionWindowMs: Int)(
       autoConfirm: AutoConfirm,
       validation: MessageValidation = MessageValidation.none): TestStep = new TestStep {
 
     override def description: List[Comment] =
       PluginSteps.generateUnsolicitedEvents().description ++
-        expectEventsUnsolicited(holdOffMs, unsolConfirmTimeoutMs)(autoConfirm, validation).description
+        expectEventsUnsolicited(holdOffMs, unsolConfirmTimeoutMs, toleranceMs)(autoConfirm, validation).description
 
     override def run(driver: TestDriver): List[DeferredCheck] = {
       val action = driver.reporter.plugin.generateUnsolicitedEvents(
@@ -74,7 +81,7 @@ object UnsolicitedResponseSteps {
         FrameValidator.none,
         withEvents(validation),
         LinkOverride.default,
-        Some(eventsTimeoutMs(holdOffMs, unsolConfirmTimeoutMs) + extraMs),
+        Some(eventsTimeoutMs(holdOffMs, unsolConfirmTimeoutMs, toleranceMs) + extraMs),
         noResponse
       ).run(driver)
     }
@@ -89,7 +96,8 @@ object UnsolicitedResponseSteps {
       options.get(data.support),
       otherSupportedClasses(data, options),
       options.get(UnsolicitedOptions.unsolicitedConfirmTimeoutMs),
-      options.get(UnsolicitedOptions.holdOffMs)
+      options.get(UnsolicitedOptions.holdOffMs),
+      options.get(TestOptions.timingToleranceMs)
     )
   }
 
@@ -104,8 +112,9 @@ object UnsolicitedResponseSteps {
       supportsClass: Boolean,
       otherClasses: List[EventClass],
       unsolConfirmTimeoutMs: Int,
-      holdOffMs: Int): List[LabeledStep] = {
-    val unconfirmed = new UnconfirmedResponse(unsolConfirmTimeoutMs)
+      holdOffMs: Int,
+      toleranceMs: Int): List[LabeledStep] = {
+    val unconfirmed = new UnconfirmedResponse(unsolConfirmTimeoutMs, toleranceMs)
     val eventClass = data.eventClass
     val classVariation = data.variation
     // step 12: a retry carries at least the events of the response it repeats; analog events may carry current values,
@@ -121,14 +130,14 @@ object UnsolicitedResponseSteps {
       3 -->
         (if (supportsClass) PluginSteps.generateClassEvents(eventClass)
          else describe(s"Device cannot generate Class ${classVariation.clazz} data")),
-      4 --> expectNoEventsUnsolicited(holdOffMs, unsolConfirmTimeoutMs),
+      4 --> expectNoEventsUnsolicited(holdOffMs, unsolConfirmTimeoutMs, toleranceMs),
       5 --> send(enableUnsolicitedResponses(Sequence.one, classVariation)),
       6 --> expectNullResponse(Sequence.one)
     )
 
     val steps7to15 = if (supportsClass) List(
       // the retries are timed from this response and the next, so a manual answer here waits until the steps are done
-      (7 to 10) --> expectEventsUnsolicited(holdOffMs, unsolConfirmTimeoutMs)(
+      (7 to 10) --> expectEventsUnsolicited(holdOffMs, unsolConfirmTimeoutMs, toleranceMs)(
         unconfirmed.hold,
         PluginValidations.verifyOldAndNewClassEvents(eventClass).deferrable && recorder.record),
       (11 to 13) --> unconfirmed.expectRetry(sameEvents.deferrable && recorder.record, AutoConfirm.Wrong),
@@ -140,7 +149,7 @@ object UnsolicitedResponseSteps {
 
     val steps16to17 = List(
       16 --> PluginSteps.generateClassEvents(otherClasses),
-      17 --> expectNoEventsUnsolicited(holdOffMs, unsolConfirmTimeoutMs)
+      17 --> expectNoEventsUnsolicited(holdOffMs, unsolConfirmTimeoutMs, toleranceMs)
     )
 
     steps1to6 ++ steps7to15 ++ steps16to17
@@ -169,21 +178,22 @@ object UnsolicitedResponseSteps {
       appConfirmTimeoutMs: Int,
       holdOffMs: Int,
       tables: Validations.Tables,
-      actionWindowMs: Int): Iterable[LabeledStep] = {
+      actionWindowMs: Int,
+      toleranceMs: Int): Iterable[LabeledStep] = {
     val messageRecorder = new MessageRecorder
 
     val seq = MutableSequence.zero
 
     def expectEvents(autoConfirm: AutoConfirm, validation: MessageValidation = MessageValidation.none): TestStep =
-      expectEventsUnsolicited(holdOffMs, unsolConfirmTimeoutMs)(autoConfirm, validation)
+      expectEventsUnsolicited(holdOffMs, unsolConfirmTimeoutMs, toleranceMs)(autoConfirm, validation)
     def generateAndExpect(autoConfirm: AutoConfirm, validation: MessageValidation = MessageValidation.none): TestStep =
-      generateAndExpectEvents(holdOffMs, unsolConfirmTimeoutMs, actionWindowMs)(autoConfirm, validation)
-    val unconfirmedUnsolicited = new UnconfirmedResponse(unsolConfirmTimeoutMs)
-    val unconfirmedPolled = new UnconfirmedResponse(appConfirmTimeoutMs)
+      generateAndExpectEvents(holdOffMs, unsolConfirmTimeoutMs, toleranceMs, actionWindowMs)(autoConfirm, validation)
+    val unconfirmedUnsolicited = new UnconfirmedResponse(unsolConfirmTimeoutMs, toleranceMs)
+    val unconfirmedPolled = new UnconfirmedResponse(appConfirmTimeoutMs, toleranceMs)
     // an unsolicited retry comes within a confirm timeout, plus the tolerance expectRetry allows, of the response it
     // repeats, so no response in that window means no more retries; 8.11.2.5.9 only counts its retries, so it doesn't
     // check they come no sooner, as expectRetry does
-    val retryWindowMs = Some(unsolConfirmTimeoutMs + UnconfirmedResponse.timingToleranceMs)
+    val retryWindowMs = Some(unsolConfirmTimeoutMs + toleranceMs)
     def expectRetry(autoConfirm: AutoConfirm): TestStep = expectUnsolicitedResponse(
       autoConfirm,
       FrameValidator.none,
@@ -329,7 +339,7 @@ object UnsolicitedResponseSteps {
       )
   }
 
-  def offSteps(unsolConfirmTimeoutMs: Int, holdOffMs: Int): Iterable[LabeledStep] = {
+  def offSteps(unsolConfirmTimeoutMs: Int, holdOffMs: Int, toleranceMs: Int): Iterable[LabeledStep] = {
     List(
       1 --> PluginSteps.enableUnsolicitedResponse(false),
       2 --> PluginSteps.cyclePower,
@@ -340,10 +350,10 @@ object UnsolicitedResponseSteps {
       7 --> send(Requests.readClass123(Sequence.one)),
       8 --> expectAtLeastOneResponse(Sequence.one),
       9 --> PluginSteps.generateUnsolicitedEvents(),
-      10 --> expectNoEventsUnsolicited(holdOffMs, unsolConfirmTimeoutMs),
+      10 --> expectNoEventsUnsolicited(holdOffMs, unsolConfirmTimeoutMs, toleranceMs),
       11 --> send(enableUnsolicitedResponses(Sequence.two)),
       12 --> expectSingleResponse(Sequence.two, containing(IIN.FUNC_NOT_SUPPORTED)),
-      13 --> expectNoEventsUnsolicited(holdOffMs, unsolConfirmTimeoutMs),
+      13 --> expectNoEventsUnsolicited(holdOffMs, unsolConfirmTimeoutMs, toleranceMs),
       14 --> send(disableUnsolicitedResponses(Sequence.three)),
       15 --> expectSingleResponse(Sequence.three, containing(IIN.FUNC_NOT_SUPPORTED))
     )

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

@@ -4,11 +4,10 @@
 package io.stepfunc.dnp3c.conformance.v27
 
 import io.stepfunc.dnp3c.conformance.api._
-import io.stepfunc.dnp3c.conformance.api.options.{ LinkOptions, SupportOptions, UnsolicitedOptions }
+import io.stepfunc.dnp3c.conformance.api.options.{ LinkOptions, SupportOptions, TestOptions, UnsolicitedOptions }
 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._
@@ -22,7 +21,8 @@ object Procedure8_11_2_1 extends ProcedureDefinition {
   override protected def steps(options: OptionSource): Iterable[LabeledStep] = {
     val unsolConfirmTimeoutMs = options.get(UnsolicitedOptions.unsolicitedConfirmTimeoutMs)
     val holdOffMs = options.get(UnsolicitedOptions.holdOffMs)
-    val restartResponse = new UnconfirmedResponse(unsolConfirmTimeoutMs)
+    val toleranceMs = options.get(TestOptions.timingToleranceMs)
+    val restartResponse = new UnconfirmedResponse(unsolConfirmTimeoutMs, toleranceMs)
     val nullWithRestart = Validations.containing(IIN.DEVICE_RESTART) && Validations.isNull
     val originalAddress = options.get(LinkOptions.source)
     val otherMasterAddress = options.get(UnsolicitedOptions.otherMasterAddress)
@@ -56,11 +56,11 @@ object Procedure8_11_2_1 extends ProcedureDefinition {
       // 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),
+      24 --> expectDeferrableAnswer(responseTimeoutMs(options), unsolConfirmTimeoutMs, toleranceMs, 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)
+      30 --> expectNoEventsUnsolicited(holdOffMs, unsolConfirmTimeoutMs, toleranceMs)
     )
   }
 
@@ -69,14 +69,15 @@ object Procedure8_11_2_1 extends ProcedureDefinition {
   private def expectDeferrableAnswer(
       responseTimeoutMs: Int,
       confirmTimeoutMs: Int,
+      timingToleranceMs: Int,
       unsolicitedResponse: UnconfirmedResponse): TestStep = new TestStep {
     private val read = expectAtLeastOneResponse(Sequence.one)
-    private val timeoutMs = responseTimeoutMs + confirmTimeoutMs + TestDriver.readToleranceMs
+    private val timeoutMs = responseTimeoutMs + confirmTimeoutMs + timingToleranceMs
 
     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
+        s"$timingToleranceMs ms)" :: read.description
 
     override def run(driver: TestDriver): List[DeferredCheck] = {
       driver.readAllResponses(Sequence.one, AutoConfirm.Yes, firstTimeoutMs = Some(timeoutMs))

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

@@ -26,7 +26,8 @@ class UnsolicitedAndPolledResponses(retryLimit: OptionSource => RetryLimit) exte
       options.get(OutstationOptions.appConfirmTimeout),
       options.get(UnsolicitedOptions.holdOffMs),
       Validations.Tables(options),
-      options.get(TestOptions.manualActionWindowMs)
+      options.get(TestOptions.manualActionWindowMs),
+      options.get(TestOptions.timingToleranceMs)
     )
   }
 }

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

@@ -4,7 +4,7 @@
 package io.stepfunc.dnp3c.conformance.v27
 
 import io.stepfunc.dnp3c.conformance.api._
-import io.stepfunc.dnp3c.conformance.api.options.{ SupportOptions, UnsolicitedOptions }
+import io.stepfunc.dnp3c.conformance.api.options.{ SupportOptions, TestOptions, UnsolicitedOptions }
 import io.stepfunc.dnp3c.conformance.common.UnsolicitedResponseSteps
 
 object Procedure8_11_2_6 extends ProcedureDefinition {
@@ -14,6 +14,7 @@ object Procedure8_11_2_6 extends ProcedureDefinition {
   override protected def steps(options: OptionSource): Iterable[LabeledStep] = {
     UnsolicitedResponseSteps.offSteps(
       options.get(UnsolicitedOptions.unsolicitedConfirmTimeoutMs),
-      options.get(UnsolicitedOptions.holdOffMs))
+      options.get(UnsolicitedOptions.holdOffMs),
+      options.get(TestOptions.timingToleranceMs))
   }
 }

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

@@ -5,7 +5,7 @@ package io.stepfunc.dnp3c.conformance.v27
 
 import io.stepfunc.dnp3c.conformance.v31r1.Rules
 import io.stepfunc.dnp3c.conformance.api._
-import io.stepfunc.dnp3c.conformance.api.options.{ OutstationOptions, SupportOptions }
+import io.stepfunc.dnp3c.conformance.api.options.{ OutstationOptions, SupportOptions, TestOptions }
 import io.stepfunc.dnp3c.conformance.common.GenericSteps._
 import io.stepfunc.dnp3c.conformance.common.UnconfirmedResponse
 import io.stepfunc.dnp3c.conformance.common.Validations._
@@ -21,7 +21,7 @@ object Procedure8_9_2_2 extends ProcedureDefinition {
   override protected def steps(options: OptionSource): Iterable[LabeledStep] = {
 
     val confirmTimeout = options.get(OutstationOptions.appConfirmTimeout)
-    val pending = new UnconfirmedResponse(confirmTimeout)
+    val pending = new UnconfirmedResponse(confirmTimeout, options.get(TestOptions.timingToleranceMs))
     // past the application confirmation timeout: a second longer
     val pastConfirmTimeout = confirmTimeout + 1000
     // inside the application confirmation timeout: half of it