Relay is failing to get the status of Appium on Se 4.16

[AC]

Hello,

I am attempting to experiment with connecting our hardware devices with Appium to make them available on a Selenium Grid. When I started this effort, Selenium was around version 4.10 and worked fine with all components running on a local workstation in a very simple configuration (pretty much just the defaults).

My efforts had to be directed elsewhere since then, and now that I can put some time on this again we are now on Selenium 4.16, and the same Appium, Selenium node, and Selenium hub configuration are now failing to talk to each other at all. Specifically, the relay seems to be unable to succeed at a status check of the Appium server. That same status request works fine in a browser or using Postman, and Appium is operating normally.

I am using OpenJDK 11, which has been mentioned as a specific requirement in the few places where recent relay problems are mentioned. As far as I can tell, I'm using all the right configuration values for the relay itself, but the documentation for this setup is not up to date on either the Selenium or Appium project docs, so perhaps I'm missing something introduced since then.

This is one of the vague stacktraces that the relay produces:

===

10:39:58.087 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.signalError] - [pool-2-thread-1] [227ms] SocketTube(2) got read error: java.io.IOException: connection closed locally

10:39:58.087 DEBUG [Http1Exchange.lambda$sendHeadersAsync$3] - [pool-2-thread-1] [227ms] Http1Exchange asyncReceiver finished (failed=jdk.internal.net.http.common.ConnectionExpiredException: subscription is finished)

10:39:58.089 DEBUG [SeleniumSpanExporter$1.lambda$export$4] - SpanData{spanContext=ImmutableSpanContext{traceId=8eb8355d23f9966823c263fcf4bd074e, spanId=b24d32e40fc3bbfa, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, resource=Resource{schemaUrl=https://opentelemetry.io/schemas/1.20.0, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.28.0"}}, instrumentationScopeInfo=InstrumentationScopeInfo{name=default, version=null, schemaUrl=null, attributes={}}, name=httpclient.execute, kind=INTERNAL, startEpochNanos=1705685997965000000, endEpochNanos=1705685998087052900, attributes=AttributesMap{data={http.method=GET, span.kind=client, http.target=http://localhost:4723/status}, capacity=128, totalAddedValues=3}, totalAttributeCount=3, events=[], totalRecordedEvents=0, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=UNSET, description=}, hasEnded=true}

10:39:58.091 WARN [RelaySessionFactory.isServiceUp] - Error checking service status http://localhost:4723/status. java.io.IOException: HTTP/1.1 header parser received no bytes

10:39:58.093 DEBUG [RelaySessionFactory.isServiceUp] - Error checking service status http://localhost:4723/status

java.io.UncheckedIOException: java.io.IOException: HTTP/1.1 header parser received no bytes

    at org.openqa.selenium.remote.http.jdk.JdkHttpClient.execute0(JdkHttpClient.java:442)

    at org.openqa.selenium.remote.http.AddSeleniumUserAgent.lambda$apply$0(AddSeleniumUserAgent.java:42)

    at org.openqa.selenium.remote.http.Filter.lambda$andFinally$1(Filter.java:55)

    at org.openqa.selenium.remote.http.jdk.JdkHttpClient.execute(JdkHttpClient.java:358)

    at org.openqa.selenium.remote.tracing.TracedHttpClient.execute(TracedHttpClient.java:54)

    at org.openqa.selenium.grid.node.relay.RelaySessionFactory.isServiceUp(RelaySessionFactory.java:220)

    at org.openqa.selenium.grid.node.local.SessionSlot.isRelayServiceUp(SessionSlot.java:186)

    at org.openqa.selenium.grid.node.local.LocalNode.getStatus(LocalNode.java:886)

    at org.openqa.selenium.grid.node.local.LocalNode.lambda$new$0(LocalNode.java:178)

    at org.openqa.selenium.grid.node.httpd.NodeServer$1.lambda$start$1(NodeServer.java:213)

    at dev.failsafe.Functions.lambda$toCtxSupplier$9(Functions.java:228)

    at dev.failsafe.Functions.lambda$get$0(Functions.java:46)

    at dev.failsafe.internal.RetryPolicyExecutor.lambda$apply$0(RetryPolicyExecutor.java:74)

    at dev.failsafe.SyncExecutionImpl.executeSync(SyncExecutionImpl.java:187)

    at dev.failsafe.FailsafeExecutor.call(FailsafeExecutor.java:376)

    at dev.failsafe.FailsafeExecutor.run(FailsafeExecutor.java:220)

    at org.openqa.selenium.grid.node.httpd.NodeServer$1.lambda$start$2(NodeServer.java:208)

    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)

    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)

    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)

    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)

    at java.base/java.lang.Thread.run(Thread.java:834)

Caused by: java.io.IOException: HTTP/1.1 header parser received no bytes

    at java.net.http/jdk.internal.net.http.common.Utils.wrapWithExtraDetail(Utils.java:291)

    at java.net.http/jdk.internal.net.http.Http1Response$HeadersReader.onReadError(Http1Response.java:656)

    at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.checkForErrors(Http1AsyncReceiver.java:297)

    at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.flush(Http1AsyncReceiver.java:263)

    at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SynchronizedRestartableTask.run(SequentialScheduler.java:175)

    at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:147)

    at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198)

    ... 3 more

Caused by: java.io.EOFException: EOF reached while reading

    at java.net.http/jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber.onComplete(Http1AsyncReceiver.java:591)

    at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadSubscription.signalCompletion(SocketTube.java:632)

    at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.read(SocketTube.java:833)

    at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowTask.run(SocketTube.java:175)

    at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198)

    at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:271)

    at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:224)

    at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.signalReadable(SocketTube.java:763)

    at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent.signalEvent(SocketTube.java:941)

    at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowEvent.handle(SocketTube.java:245)

    at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.handleEvent(HttpClientImpl.java:957)

    at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.lambda$run$3(HttpClientImpl.java:912)

    at java.base/java.util.ArrayList.forEach(ArrayList.java:1540)

    at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:912)

10:39:58.094 ERROR [NodeServer$1.lambda$start$1] - Node is not alive: http://192.168.1.86:5555 is DOWN

===

According to the Appium server logs, no incoming request is recorded. I can use a browser or other tool to ask for the content of that status endpoint without any errors, but whatever the relay is doing is not equivalent to those applications. I've tested this on both Windows and Mac to the same end result. On the Mac, there is also no firewall in play, and the Windows firewall appears to be fully permissive.

If I downgrade my Selenium jarfile back to 4.10 with no additional changes, there are no problems from any of these applications. The relay registers with the hub and shows whatever it has been configured to show on behalf of the Appium server. This also works fine regardless of OS.

Comments in the handful of issues I could find suggest that Selenium project maintainers have not been able to reproduce reports like this, but I can't tell what I might be missing considering how simple the relay is presented to be in the docs.

Does anyone have any insight on this? Relays don't seem to be very widely used, unfortunately.