[jwrosewell]

Problem

In full build 43382362370 (head b96922b1 of #91), the job MacOS_X64_Java_17 failed in the geo-location cloud value tests. The first test waited 30.63 seconds, then all three threw, and the log does not say why.

[ERROR] ValueTests_Cloud_AvailableProperties(fiftyone.geolocation.data.tests.FiftyoneValueTests)  Time elapsed: 30.63 s  <<< ERROR!
fiftyone.pipeline.exceptions.AggregateException: Exception(s) occurred processing evidence.
	at fiftyone.geolocation.data.tests.FiftyoneValueTests.ValueTests_Cloud_AvailableProperties(FiftyoneValueTests.java:47)
[ERROR] ValueTests_Cloud_ValueTypes(fiftyone.geolocation.data.tests.FiftyoneValueTests)  Time elapsed: 0.003 s  <<< ERROR!
[ERROR] ValueTests_Cloud_TypedGetters(fiftyone.geolocation.data.tests.FiftyoneValueTests)  Time elapsed: 0.019 s  <<< ERROR!

The Cloud Request Engine's timeout is 2 seconds by default (Constants.java line 41).

Which wait was 30 seconds, and whose

The engine applies its timeout as the connect and read timeouts of each HttpURLConnection (CloudRequestEngineDefault.java lines 830 to 835). Neither covers the lookup of the host name. The connection looks the host up before its connect timeout starts, and the lookup waits for as long as the operating system's resolver does.

A probe on a macos-15-intel runner (run 43435285991), with Java 17.0.20.1 on macOS 15.7.9 as in the failing job, sent lookups for 51degrees.com to an address that never answers and timed them.

What was timed	Result
Lookup of cloud.51degrees.com, resolver answering	40 ms
Request with connect and read timeouts of 2000 ms, resolver not answering	failed after 30,453 ms with UnknownHostException
The same request straight after	failed after 0 ms
A lookup 11 seconds later	failed after 30,005 ms

So the 30 seconds is the macOS resolver giving up on a DNS server that does not answer. The JVM then keeps the failed lookup for 10 seconds, which is why the second and third tests failed in 3 ms and 19 ms. That is the shape of the failure.

The test class takes these times when the cloud answers, over the 14 full build attempts between 11 and 13 November (13 runs, one of them run twice). Only some of them ran the macOS jobs.

Runner	Passing runs	Shortest	Longest
Ubuntu_Java_8	14	1.36 s	1.86 s
Ubuntu_Java_11	14	1.37 s	2.27 s
Ubuntu_Java_17	14	1.42 s	2.10 s
Ubuntu_Java_21	14	1.46 s	3.32 s
Ubuntu_ARM_Java_17	14	1.48 s	1.99 s
Windows_Java_8	14	1.55 s	3.13 s
Windows_Java_11	14	1.75 s	2.98 s
Windows_Java_17	14	1.72 s	3.33 s
Windows_Java_21	14	1.60 s	2.99 s
MacOS_Java_11	5	1.69 s	2.81 s
MacOS_Java_17	5	2.04 s	2.46 s
MacOS_Java_21	5	1.11 s	2.56 s
MacOS_X64_Java_11	5	2.09 s	3.94 s
MacOS_X64_Java_17	4	2.93 s	3.98 s
MacOS_X64_Java_21	5	2.77 s	3.48 s

No runner is near 30 seconds, so no limit needs to change. The wait was not the test's or the engine's, and it was longer than the engine's timeout says a request can take.

Why the cause was not in the log

1. PipelineDefault.process throws an AggregateException that holds the element's exception only as a suppressed exception (PipelineDefault.java lines 495 to 504, AggregateException.java line 48). Surefire 2.22.2 trims a stack trace to the test's own frames, so the cause is not printed.
2. FlowDataDefault.addError logged Error occurred during processing of ... without the exception (FlowDataDefault.java line 124).
3. The location packages took SLF4J 1.7.36 (location/pom.xml line 66) with Logback 1.3.16, which binds only through the SLF4J 2 API. Their tests logged nothing at all, as the failing job printed.

   SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
   SLF4J: Defaulting to no-operation (NOP) logger implementation
   

   That also dropped the engine's warning when it is built, which carries the exception (CloudRequestEngineDefault.java line 364).

What changed

1. HttpClientDefault looks up the host within the connection's connect timeout before it connects, through the new HostLookup in pipeline.engines. A lookup that takes longer throws SocketTimeoutException: Looking up the host 'cloud.51degrees.com' took longer than the timeout of 2000 ms. A lookup that succeeds leaves the address in the JVM's cache, where the connection then finds it. Callers waiting on the same host share one lookup, so a resolver that does not answer holds one thread, not one for each request. Nothing is looked up when the connect timeout is 0, which means no limit, or when a proxy makes the request, because the proxy looks up the host. The Cloud Request Engine uses HttpClientDefault unless it is given another client, so its timeout now covers the lookup.

   Relying on the JVM's cache has two limits, which HostLookup's comment also says. With the security property networkaddress.cache.ttl set to 0 nothing is cached, so the connection looks the host up again itself, with no limit, as before this change. And every request is looked up first, including one the connection would have sent on a kept-alive socket with no lookup at all. So once the cached address expires, 30 seconds after it was found by default, a resolver that does not answer now fails such a request within the timeout, where before the open socket would have served it. Avoiding that would need either a thread for each request's whole connect, which a resolver that does not answer would hold for 30 seconds each, or a way to hand the connection an address, which HttpURLConnection on Java 8 does not have.

   The default ProxySelector decides whether a request goes through a proxy. A subclass of HttpClientDefault whose connect opens the connection through a proxy of its own still has the host looked up here, which HttpClientDefault's comment says.

2. FlowDataDefault.addError logs the exception with the error.

3. The location packages take SLF4J 2.0.20, as the other five package trees do.

4. GeoLocationCloudEngine, DeviceDetectionCloudEngine, IPIntelligenceCloudEngine and the developer example's SimpleCloudEngine override processEngine and read the cloud response without the check that CloudAspectEngineBase.processEngine makes (CloudAspectEngineBase.java lines 425 to 439). A failed cloud request leaves no response, so each one added NullPointerException: Cannot invoke "String.length()" because "s" is null after the real error. The fault run 43437302629 on this branch showed it, once logging worked and before this check was added. Each now logs one warning, Constants.Messages.NoCloudResponse, and processes nothing.

5. CloudAspectEngineBase.processEngine logs the same NoCloudResponse warning in place of its own copy of the text.

How it was verified

New tests:

• HostLookupTests, 8 tests. A resolver that does not answer times out within the limit with the host in the message, an unknown host keeps its cause, a timeout of 0 looks nothing up, a lookup after a failure looks up again, two callers at once share one lookup, a request through a proxy looks nothing up, and both request methods of HttpClientDefault fail within the connect timeout.
• FlowDataTests.FlowData_AddError_LogsTheException.
• NoResponse_ProcessesNothing in GeoLocationCloudEngineNullValueTests and in the Device Detection and IP Intelligence cloud ProductMissingTests, each checking that one warning is logged for each response.

Run against rc with only the tests and the new message constant added (run 43518934300), FlowData_AddError_LogsTheException fails with Argument(s) are different!, because the error is logged without the exception, and the three NoResponse_ProcessesNothing tests fail with NullPointerException: Cannot invoke "String.length()" because "s" is null. On this head (run 43518954543) all four pass, with the 8 HostLookupTests.

Fault runs on ubuntu-22.04 build the packages, run the geo-location cloud value tests with the cloud answering, then send every name lookup to an address that never answers, with a resolver timeout of 30 seconds as on macOS, and run them again.

	rc (run 43437315713)	this change (run 43439842768)
Cloud answering	passed in 1.44 s	passed in 1.55 s
Not answering, first test	30.19 s	4.23 s
Not answering, second and third tests	0.013 s and 0.014 s	4.03 s and 4.03 s
Cause in the log	none, the SLF4J no-operation logger	SocketTimeoutException: Looking up the host 'cloud.51degrees.com' took longer than the timeout of 2000 ms. in the engine's warning and in the processing error

Each test now takes 4 seconds under the fault, being the 2 second limit on the lookup when the engine is built and again when it processes. Both fault runs show as cancelled, because once the runner could not look up names it could not report back, but every step had finished and the job pages show their results.

Full build: none on this head, 35ac923f, which has rc 30e4886 merged in. The full build 43441956524 of the earlier head dd8d7356 passed in 14 of its 15 build and test jobs across its two attempts, every PullRequestSha equal to that head, the Intel macOS Java 11 job among them with FiftyoneValueTests in 3.21 s and HostLookupTests in 1.03 s. MacOS_X64_Java_21 failed in both attempts in the Selenium contract test that #124 fixes, which does not touch this change. This draft is built again with macOS once #124 is in rc and rc is merged in here.

What remains

• DataUploaderHttp, ShareUsageElement and DidClient open their own connections, so their lookups still wait as long as the resolver does. None of them is the Cloud Request Engine.
• DataUpdateServiceDefault connects through HttpClient.connect and then calls getResponseCode itself (lines 821 and 838), not through postData or getResponseString, so the lookups of data file downloads have no limit either.
• Why the runner's DNS server stopped answering during that job is outside this repository.