[jwrosewell]

The problem

The nightly build of rc at 8f14aa0 failed on Windows_Node_24 in
run 43356655077
(the job "Nightly PR - 0", which builds rc). One test failed, being
log messages › a download cut short is the no response error in
pipeline/fiftyone.pipeline.engines/tests/dataUpdateSpecification.test.js.

Expected: "Error during check for data update. Error detail: No response from data update service at 'http://127.0.0.1:60867/datafile' for engine 'TestEngine'"
Received: "Error during check for data update. Error detail: Error accessing data update service at 'http://127.0.0.1:60867/datafile' for engine 'TestEngine'. Error detail: read ECONNRESET"

The test
(lines 526 to 546 at 8f14aa04)
starts a check and closes every connection 10 milliseconds later, with
setTimeout(() => remote.server.closeAllConnections(), 10) at line 537,
whether or not the response has arrived. The service writes a different
message for each order.

• When the response arrives first, the response's close handler logs "No
  response from data update service"
  (dataFileUpdateService.js lines 525 to 538).
• When the close comes first, the request fails, and its error handler logs
  "Error accessing data update service" with the cause
  (lines 432 to 443).

So the test passed or failed by chance. Of the 68 Windows build and test
jobs that ran a tree holding this test, from when it was added on
11 November to the morning of 13 November, it failed in that one nightly
job. Another job, run 43036532489,
failed for a different reason. Run on its own 60 times on windows-latest
it passed every time
(run 43412245194,
job "rc as it is windows-latest"), so the failure is rare, and the one
failure seen came in a full test run.

A second fault showed once the reset test no longer waited a fixed time.
The close handler destroyed the write stream for the part file, asked for
the file to be removed, and reported the update straight away. The removal
runs on another thread, so the part file could still be in the temporary
folder when the update was reported, and the old reset test's check of the
folder held only because it waited 500 milliseconds first.

What the specification says

The Errors section of data-updates.md, lines 461 to 505 at 6570727d
says which message each failure carries.

A row at Error level is an error that carries the message shown. Where the
service logs it, the entry is at Error, reads Error during check for data update, and has the error attached.

These messages MUST also be consistent across languages to make life easier
for 51Degrees support. They are the messages and levels of the .NET data
update service, and each status is the one .NET reports.

Error	Log level	Status	Message
Connecting to the data update URL failed	Error	AUTO_UPDATE_HTTPS_ERR	Error accessing data update service at '<url>' for engine '<Engine type name>'
The data update URL gave no response	Error	AUTO_UPDATE_HTTPS_ERR	No response from data update service at '<url>' for engine '<Engine type name>'

Neither row names a download cut short, so the sentence that decides is the
one saying the messages are those of the .NET service. In .NET,
DataUpdateService.cs lines 1305 to 1326
sends the request with _httpClient.SendAsync(message) inside a try, and
the catch throws "Error accessing data update service at '{shownUrl}' for
engine '...'" with the exception attached. That form of SendAsync, as
Microsoft's documentation
says, "will complete once the entire response including content is read".
So a download cut short fails inside that call, and .NET reports it as
"Error accessing data update service", with the cause attached. .NET writes
"No response from data update service" only when SendAsync returns no
response object.

Node's message for a download cut short was therefore not the one the
specification gives, and the test expected that message as well as
depending on the timer.

What changed

Five commits, each fix after the tests that show it.

1. 53c0111, tests.
   • a download cut short is the error for a service that could not be reached replaces the failing test. A server sends the headers with
     content-length: 1000 and 7 bytes, and never sends the rest. A spy on
     http.get closes the connections when the service's request has its
     response, so the cut always comes part way through the download.
   • a connection closed before any response is the same error is new,
     and covers the other order. The server closes the connection as soon
     as the request arrives.
   • a connection reset part way through the download is reported once and schedules one check expects the same error.
   • The expected message is matched in full up to the cause, and any cause
     is accepted, because its wording differs between platforms (aborted,
     read ECONNRESET, socket hang up).
2. 1e37ee6, dataFileUpdateService.js. The response's close handler for a
   download cut short logs the same "Error accessing data update service"
   text the request's error handler uses (accessError), with the cause
   attached. The cause is the first error the request or the response raised
   after the response arrived, which the two error handlers now keep where
   they used to drop it. The status, AUTO_UPDATE_HTTPS_ERR, is unchanged.
   Node no longer writes "No response from data update service". .NET writes
   it only when SendAsync returns no response object, and Node's
   http.get has no outcome of that kind.
3. 035b82b, tests. The reset test no longer resets 50 milliseconds after the
   server writes or waits 500 milliseconds. It resets once the service's
   request has its response, waits for the update to be reported, and then
   checks there is one report, one scheduled check and no part file. The cut
   short test checks the folder too. In both the cut comes before the
   service opens its part file.
4. 104bbb9, dataFileUpdateService.js. The close handler removes the part
   file once the write stream has closed, which is after the file is open,
   and reports the update once the file has gone.
5. 1c1da8e, tests. The folder checks of commit 3 passed or failed by chance
   on the service before commit 4, so a spy on fs.unlink now records each
   removal as it finishes, and both tests check that the part file's removal
   had finished when the update was reported.

The three tests this draft changes or adds
(lines 581, 617 and 968 at 1c1da8e)
use no timer. Other tests in the file still wait fixed times, at lines
811,
884, 890, 931, 942 and 954, 1033, 1078, 1128, 1159, 1185 and 1212, and the
serve helper ends its response after 50 milliseconds at line 86. They are
not changed here.

How it was verified

Each test job runs the test file 10 or 60 times, with the flags of the
repository's unit-test script (--ci --runInBand --forceExit --coverage).

Run	Job	Code	Result
43412245194	red, Windows and Ubuntu	tests of 53c0111 on the rc service	0 of 10 passed on each. Both changed tests failed every run, receiving "No response from data update service"
43412245194	green, Windows and Ubuntu	1e37ee6	60 of 60 passed on each, and eslint is clean
43436746478	red, Windows and Ubuntu	tests of 1c1da8e on the service of 1e37ee6	0 of 10 passed on each. Both cut short tests failed every run, with Expected: 1, Received: 0 removals when the update was reported
43436746478	green, Windows and Ubuntu	1c1da8e	60 of 60 passed on each, and eslint is clean

Run 43430331608
also cut 200 downloads short in a script outside the tests and counted part
files. On the service of 1e37ee6 the part file was still there when the
update was reported in 6 of 200 on Windows and 29 of 200 on Ubuntu, and gone
200 milliseconds later in all 400. So the file was removed late, but no file
was left behind for good, which is the fault read from the code before. On
104bbb9 the count was 0 at the report each time. In the same run the tests
of 035b82b on the older service failed in 1 of 10 runs on Windows and 0 of
10 on Ubuntu, which is why commit 5 checks the order of removal and report
rather than the folder alone.

Full builds, with every Setting 'PullRequestSha' line on the commit named.

• Run 43414741118
  at 1e37ee6 passed. All 8 Ubuntu, Ubuntu ARM, Windows and macOS jobs on
  Node.js 22 and 24 succeeded, each with 1,356 unit tests passed and 132
  integration tests passed.
• Run 43436807511
  at 1c1da8e. The 6 Ubuntu, Ubuntu ARM and Windows jobs passed, each with
  1,356 unit tests and 132 integration tests passed. macOS_Node_24 failed
  one test this draft does not touch,
  the time of a read with the native engine › a read by name is no slower than it was in
  device-detection/fiftyone.devicedetection.onpremise/tests/propertyNameCaseNative.test.js line 164,
  which measured 1,460.94 nanoseconds against a limit of 1,385.96, being a
  tenth above the 1,260 it measured for the read before. macOS_Node_22 was
  cancelled. That failure is a timing test of its own, fixed in
  #96.

Effect on applications

A log search or an alert keyed on "No response from data update service" no
longer matches anything Node writes. A download cut short now reads "Error
during check for data update. Error detail: Error accessing data update
service at '<url>' for engine '<name>'. Error detail: <cause>", as .NET
writes it, and is reported once its part file has been removed. The status
reported to updateComplete listeners is unchanged.

What remains

• The macOS timing test above fails on timing, so under "Tests that fail on
  timing" in AGENTS.md it is fixed rather than run again, in its own
  draft, #96. This
  draft's full build can pass on macOS once Settle the native read timing test on paired rounds, and count the case work #96 is in rc.
• The specification's description of the first row, "Connecting to the data
  update URL failed", is narrower than what .NET reports under it, because a
  failure while the body is read is reported the same way. That is
  specifications#144.
• The other languages report a download cut short in a way that matches
  neither row, as read from each one's rc code.
  • Java logs it at warning with its own message,
    51degrees-java#125.
  • Go reports it as the unhandled error,
    51degrees-go#123.
  • Rust reports it as StreamError with its own message,
    51degrees-rust#403.
  • Python already reports it as the access error, because requests.get
    without streaming reads the whole body inside that call
    (datafile_update_service.py lines 152 to 161 at df0949d7),
    so it needs no issue.