Message times are taken when a step reads the message, so intervals measured from it come out short #93

Activity

1. jadamcrain commented on Oct 15, 2026

   

   jadamcrain

   on Oct 15, 2026

   Member

   More actions

   Thanks for the detailed report. We looked into it, including running 8.11.2a against py1815.

   How dnp3c times this test. Over TCP, steps 21 to 28 of 8.11.2a never sleep, call the plugin or prompt. Each step waits on a read from the connection:

   • Step 24 reads the answer to step 23's READ, and returns as soon as its final fragment arrives. It doesn't wait to see whether more responses follow.
   • The runner starts step 25 straight away. Between steps it only writes the next step's heading to the log. Step 25 then waits on the connection for the next unsolicited response, and so do steps 27 and 28.
   • dnp3c's link layer decodes frames it has already received before it reads the socket again. A null that arrives in the same TCP read as the READ answer is handed to step 25 at once.
   • A step records a response's time once the response has been decoded, logged and checked. Nothing in that work waits, so the time is normally within a few milliseconds of the bytes reaching dnp3c. The retry interval is the difference between two such times, and it must be at least the confirm timeout minus 500 ms (4500 ms here).

   So nothing in the procedure holds the null back. dnp3c logged it at 14:11:11.862 because, as far as anything in the procedure is concerned, that's when it arrived.

   What we saw running it. We ran 3.1r1's 8.11.2a with dnp3c main (and 2.7's 8.11.2.1 with 0.1.0) against py1815's jj/dnp3c-conformance and jj/dnp3c-level2-fixes. We used interop/conformance_outstation.py, your device.ini with outstation.response.timeout.ms = 6000, and a 5 s unsolicited confirm timeout. It passes every time. py1815 answers the deferred READ when the confirm timeout expires and sends the next null in the same write. dnp3c receives both about 30 ms after py1815 logs them, and measures the retry at about 4970 ms.

   What differs in your run. dnp3c received the READ answer on time and the null 0.52 s later, so the two seem to have left separately, about 0.5 s apart. That matches py1815's server, which checks the session for unsolicited sends every UNSOLICITED_INTERVAL (0.5 s) unless something wakes it. If the null isn't added to the READ answer's write, it waits for the next check, while its retry timer runs from when the session built it.

   A packet capture would settle it, since it shows when each null crossed the wire. Could you share that run's log.html for 8.11.2a and its capture (tcp.capture.adapter), along with the py1815 commit and the platform (OS, Python version, Docker or not)?
2. dersecure commented on Oct 16, 2026

   

   dersecure

   on Oct 16, 2026

   Author

   More actions

   Thanks for running it. You're right, and I had the cause wrong.

   At 582493e with our normal settings (outstation.response.timeout.ms = 2000, a 5 s unsolicited confirm timeout), 8.11.2a passes three runs out of three, with no warning. In each run the null arrives 3 to 5 ms after the READ answer, and step 27 measures the retry at 4939 to 4951 ms. A full -rev 3.1r1 run at subset level 2 has 158 passed and 70 skipped, with nothing failed and no warnings. That's against py1815 #100 (c2ff329), with the fixture and plugin from our conformance branch, on Windows 11, Python 3.12.10 and OpenJDK 17.0.18, not in Docker.

   What happened in the failing run. Step 24 doesn't wait for more responses, as you said. The log of that run shows the READ answer's first bytes read at 11.369 and the last at 11.390, but the response wasn't fully decoded and checked until 11.842. Step 25 then took up the null at 11.862. In today's runs that same stretch takes about 50 ms. The machine was heavily loaded at the time by another test suite running in parallel, so I read this as dnp3c being starved of CPU while it processed a multi-frame response. py1815 builds the READ answer and the next null together and hands them to the socket in one write, and the device log for that run shows them 2 ms apart.

   So the timing is only off when processing a response takes a large share of the 500 ms tolerance. Timestamping on receipt would cover that case, but it's an edge case on an overloaded machine, not something a normal run hits. I have no capture from that run: this machine has no Npcap, so dnp3c lists no adapter. Close this or keep it as low priority, whichever you prefer. Nothing here should hold 0.2.0.

   Thanks for the fix to #1, and for checking against our branches yourselves.
3. jadamcrain commented on Oct 16, 2026

   

   jadamcrain

   on Oct 16, 2026

   Member

   More actions

   Thanks for rerunning it and for tracking down the cause. We think it's best to close this:

   We don't think a different timestamp can fix the underlying cause.

   1. The time a frame arrives can't really be measured precisely from userspace. That would take hardware timestamps from the NIC, which a Java process can't get. Every time dnp3c can observe is when the OS handed it the data, and an ASDU can span several link frames and TCP segments. The time that seems most meaningful to us is when dnp3c has the assembled ASDU, which is what it records now.
   2. A heavily loaded OS can delay anything. It can hold back the socket read just as easily as the decode that follows, so taking the timestamp earlier would only move the measurement point inside a process that's waiting for CPU.

   When the machine has CPU to spare, dnp3c is only waiting on the connection during these steps, so the time it records is within a few milliseconds of the bytes arriving. Your clean runs bear that out.

   What we changed (#97). Your report did show that the tolerance dnp3c allows on the times it measures was fixed, at 500 ms for timed intervals and 200 ms past timeouts, with no way to adjust it. It's now one option, test.timingToleranceMs, with a default of 500 ms, that you can set in device.ini. It loosens the checks both ways. A larger value only makes the steps that expect no message wait longer: a step that gets its message moves on as soon as it arrives. It will be in 0.2.0.

   For the timing tests, we'd suggest a machine that isn't busy with other work. If one fails under load, rerunning it, or raising test.timingToleranceMs, is a good first step before treating it as a device problem.

   Thanks again for the detailed reports. They've been really helpful.
4. jadamcrain

   closed this as not plannedon Oct 16, 2026