search

SeleniumHQ / selenium

A browser automation framework and ecosystem.
https://selenium.dev
Apache License 2.0
30.77k stars 8.2k forks source link

[🐛 Bug]: [GRID] SessionNotCreatedException JdkHttpClient.execute0 exactly after 60 seconds despite --session-request-timeout 360 #14307

Closed KrzysztofC closed 3 months ago

KrzysztofC commented 3 months ago

What happened?

My Hub and Nodes are running in separate containers in OpenShift. Sometimes there will be leftover processes or some general environment slowness in the Node container and then the SessionNotCreatedException happens. Setting --session-request-timeout does not help in this particular case. What happens is: Grid Hub and Node are running in separate containers. Single test is started. While in terminal on the Node, I can see chromedriver (or msedgedriver, depending on capabilities) starting and soon after, browser begins to start up. If the browser is not ready within 60 seconds due to any slowness, the error occurs.

regardless of settings, it happens after exactly 60 seconds. 14:02:34.219 DEBUG [JdkHttpClient.execute0] - Executing request: (POST) /session 14:03:34.720 DEBUG [JdkHttpClient.execute0] - Ending request (POST) /session in 60,500ms

How can we reproduce the issue?

I can reproduce this issue every time when I configure Grid Node container with fewer CPU resources to simulate slowness or conserve resources. If Chrome or Edge takes more than 60 seconds to open, then the issue will happen. Note: my route in OpenShift already has haproxy.router.openshift.io/timeout set to a higher value, but I don't think it matters in this particular case.

Relevant log output

Grid Node with FINEST logs:

14:02:32.989 DEBUG [RequestConverter.channelRead0] - Incoming message: DefaultHttpContent(data: PooledSlicedByteBuf(ridx: 0, widx: 102, cap: 102/102, unwrapped: PooledUnsafeDirectByteBuf(ridx: 432, widx: 432, cap: 432)), decoderResult: success)
14:02:32.993 DEBUG [RequestConverter.channelRead0] - Incoming message: DefaultLastHttpContent(data: PooledSlicedByteBuf(ridx: 0, widx: 192, cap: 192/192, unwrapped: PooledUnsafeDirectByteBuf(ridx: 192, widx: 192, cap: 496)), decoderResult: success)
14:02:32.993 DEBUG [RequestConverter.channelRead0] - End of http request: DefaultLastHttpContent(data: PooledSlicedByteBuf(ridx: 192, widx: 192, cap: 192/192, unwrapped: PooledUnsafeDirectByteBuf(ridx: 192, widx: 192, cap: 496)), decoderResult: success)
14:02:32.995 DEBUG [SpanWrappedHttpHandler.execute] - Wrapping request. Before OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@6b419da, context={}, span id=0000000000000000, trace id=00000000000000000000000000000000} and after OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@6b419da, context={opentelemetry-trace-span-key=SdkSpan{traceId=2d3268b08dce473e96c11409c2b93ebd, spanId=3347ea9a672869fc, parentSpanContext=ImmutableSpanContext{traceId=2d3268b08dce473e96c11409c2b93ebd, spanId=4e86788e685ec1ed, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, name=node.new_session, kind=INTERNAL, attributes=AttributesMap{data={random.key=06b74abc-aa98-4f8a-b0d6-4b7409f33b7c}, capacity=128, totalAddedValues=1}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1721916152995063159, endEpochNanos=0}}, span id=3347ea9a672869fc, trace id=2d3268b08dce473e96c11409c2b93ebd}
14:02:32.995 DEBUG [HttpTracing.inject] - Injecting (POST) /se/grid/node/session into OpenTelemetrySpan{traceId=2d3268b08dce473e96c11409c2b93ebd,spanId=3347ea9a672869fc} at org.openqa.selenium.remote.tracing.SpanWrappedHttpHandler:85
14:02:33.022 DEBUG [DriverFinder.getBinaryPaths] - Skipping Selenium Manager, path to msedgedriver specified in Service class: /opt/selenium/msedgedriver
14:02:33.024 DEBUG [DriverService.start] - Starting driver at /opt/selenium/msedgedriver with [--port=18350]
14:02:33.042 DEBUG [UrlChecker.waitUntilAvailable] - Waiting for [http://localhost:18350/status]
14:02:33.043 DEBUG [UrlChecker.lambda$waitUntilAvailable$1] - Polling http://localhost:18350/status
14:02:33.047 FINEST [HttpURLConnection.plainConnect0] - ProxySelector Request for http://localhost:18350/status
14:02:33.059 DEBUG [UrlChecker.lambda$waitUntilAvailable$1] - Polling http://localhost:18350/status
14:02:33.060 FINEST [HttpURLConnection.plainConnect0] - ProxySelector Request for http://localhost:18350/status
14:02:33.080 DEBUG [UrlChecker.lambda$waitUntilAvailable$1] - Polling http://localhost:18350/status
14:02:33.080 FINEST [HttpURLConnection.plainConnect0] - ProxySelector Request for http://localhost:18350/status
14:02:33.121 DEBUG [UrlChecker.lambda$waitUntilAvailable$1] - Polling http://localhost:18350/status
14:02:33.121 FINEST [HttpURLConnection.plainConnect0] - ProxySelector Request for http://localhost:18350/status
14:02:33.201 DEBUG [UrlChecker.lambda$waitUntilAvailable$1] - Polling http://localhost:18350/status
14:02:33.202 FINEST [HttpURLConnection.plainConnect0] - ProxySelector Request for http://localhost:18350/status
14:02:33.203 FINEST [HttpURLConnection.plainConnect0] - Proxy used: DIRECT
14:02:33.204 DEBUG [HttpURLConnection.writeRequests] - sun.net.www.MessageHeader@557d567d5 pairs: {GET /status HTTP/1.1: null}{User-Agent: Java/17.0.11}{Host: localhost:18350}{Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2}{Connection: keep-alive}
14:02:33.205 FINEST [HttpClient.logFinest] - KeepAlive stream used: http://localhost:18350/status
14:02:33.206 DEBUG [HttpURLConnection.getInputStream0] - sun.net.www.MessageHeader@55e288a44 pairs: {null: HTTP/1.1 200 OK}{Content-Length: 232}{Content-Type: application/json; charset=utf-8}{cache-control: no-cache}
14:02:33.208 FINEST [ClientVector.get] - cached HttpClient was idle for 0
14:02:34.036 DEBUG [HttpClientImpl.<init>] - [pool-2-thread-14] [807ms] HttpClientImpl(1) proxySelector is sun.net.spi.DefaultProxySelector@39562c7d (user-supplied=false)
14:02:34.163 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [933ms] HttpClientImpl(1) next timeout: 0
14:02:34.163 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [934ms] HttpClientImpl(1) next expired: 0
14:02:34.163 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [934ms] HttpClientImpl(1) Next deadline is 3000
14:02:34.219 DEBUG [JdkHttpClient.execute0] - Executing request: (POST) /session
14:02:34.229 DEBUG [HttpClientImpl.sendAsync] - [pool-2-thread-14] [999ms] HttpClientImpl(1) ClientImpl (async) send http://localhost:18350/session POST
14:02:34.239 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [1s 9ms] HttpClientImpl(1) next timeout: 299999
14:02:34.239 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [1s 9ms] HttpClientImpl(1) next expired: 0
14:02:34.239 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [1s 10ms] HttpClientImpl(1) Next deadline is 3000
14:02:34.239 DEBUG [Exchange.establishExchange] - [JdkHttpClient-0-0] [1s 10ms] Exchange establishing exchange for http://localhost:18350/session POST,
                proxy=null
14:02:34.246 DEBUG [Http2ClientImpl.getConnectionFor] - [JdkHttpClient-0-0] [1s 17ms] Http2ClientImpl not found in connection pool
14:02:34.246 DEBUG [ExchangeImpl.get] - [JdkHttpClient-0-0] [1s 17ms] ExchangeImpl get: Trying to get HTTP/2 connection
14:02:34.247 DEBUG [ExchangeImpl.createExchangeImpl] - [JdkHttpClient-0-0] [1s 17ms] ExchangeImpl handling HTTP/2 connection creation result
14:02:34.247 DEBUG [ExchangeImpl.createExchangeImpl] - [JdkHttpClient-0-0] [1s 18ms] ExchangeImpl new Http1Exchange, try to upgrade
14:02:34.254 DEBUG [PlainHttpConnection.<init>] - [JdkHttpClient-0-0] [1s 24ms] PlainHttpConnection(?) Initial receive buffer size is: 43690
14:02:34.254 DEBUG [PlainHttpConnection.<init>] - [JdkHttpClient-0-0] [1s 24ms] PlainHttpConnection(?) Initial send buffer size is: 8192
14:02:34.323 DEBUG [Exchange.checkFor407] - [JdkHttpClient-0-0] [1s 93ms] Exchange checkFor407: all clear
14:02:34.323 DEBUG [Http1Exchange.sendHeadersAsync] - [JdkHttpClient-0-0] [1s 94ms] Http1Exchange Sending headers only
14:02:34.328 DEBUG [Http1AsyncReceiver.subscribe] - [JdkHttpClient-0-0] [1s 98ms] Http1AsyncReceiver(SocketTube(1)) Subscribed pending jdk.internal.net.http.Http1Response$HeadersReader@4e11497 queue.isEmpty: true
14:02:34.332 DEBUG [Http1AsyncReceiver.handlePendingDelegate] - [JdkHttpClient-0-0] [1s 102ms] Http1AsyncReceiver(SocketTube(1)) delegate is now jdk.internal.net.http.Http1Response$HeadersReader@4e11497, demand=1, canRequestMore=true, queue.isEmpty=true
14:02:34.332 DEBUG [Http1AsyncReceiver.hasDemand] - [JdkHttpClient-0-0] [1s 103ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 1
14:02:34.334 DEBUG [Http1AsyncReceiver.checkRequestMore] - [JdkHttpClient-0-0] [1s 105ms] Http1AsyncReceiver(SocketTube(1)) checkRequestMore: canRequestMore=true, hasDemand=true
14:02:34.335 DEBUG [Http1AsyncReceiver.hasDemand] - [JdkHttpClient-0-0] [1s 105ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 1
14:02:34.335 DEBUG [Http1AsyncReceiver.checkRequestMore] - [JdkHttpClient-0-0] [1s 105ms] Http1AsyncReceiver(SocketTube(1)) checkRequestMore: canRequestMore=true, hasDemand=true
14:02:34.335 DEBUG [Http1Exchange.sendHeadersAsync] - [JdkHttpClient-0-0] [1s 105ms] Http1Exchange response created in advance
14:02:34.335 DEBUG [Http1Exchange.sendHeadersAsync] - [JdkHttpClient-0-0] [1s 106ms] Http1Exchange initiating connect async
14:02:34.338 DEBUG [PlainHttpConnection.connectAsync] - [JdkHttpClient-0-0] [1s 109ms] PlainHttpConnection(SocketTube(1)) registering connect timer: ConnectTimerEvent, TimeoutEvent[id=2, duration=PT10S, deadline=2024-07-25T14:02:44.335745960Z]
14:02:34.339 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [1s 109ms] HttpClientImpl(1) next timeout: 9996
14:02:34.339 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [1s 109ms] HttpClientImpl(1) next expired: 0
14:02:34.339 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [1s 109ms] HttpClientImpl(1) Next deadline is 3000
14:02:34.339 DEBUG [PlainHttpConnection.connectAsync] - [JdkHttpClient-0-0] [1s 109ms] PlainHttpConnection(SocketTube(1)) registering connect event
14:02:34.340 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-1-SelectorManager] [1s 111ms] SelectorAttachment Registering jdk.internal.net.http.PlainHttpConnection$ConnectEvent@29f61822 for 8 (true)
14:02:34.340 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [1s 111ms] HttpClientImpl(1) next timeout: 9995
14:02:34.340 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [1s 111ms] HttpClientImpl(1) next expired: 0
14:02:34.340 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [1s 111ms] HttpClientImpl(1) Next deadline is 3000
14:02:34.342 DEBUG [PlainHttpConnection$ConnectEvent.handle] - [HttpClient-1-SelectorManager] [1s 112ms] PlainHttpConnection(SocketTube(1)) ConnectEvent: finishing connect
14:02:34.342 DEBUG [PlainHttpConnection$ConnectEvent.handle] - [HttpClient-1-SelectorManager] [1s 113ms] PlainHttpConnection(SocketTube(1)) ConnectEvent: connect finished: true, cancelled: false, Local addr: /127.0.0.1:47204
14:02:34.343 DEBUG [PlainHttpConnection.finishConnect] - [JdkHttpClient-0-0] [1s 113ms] PlainHttpConnection(SocketTube(1)) finishConnect, setting connected=true
14:02:34.343 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [1s 114ms] HttpClientImpl(1) next timeout: 299895
14:02:34.343 DEBUG [Http1Exchange.connectFlows] - [JdkHttpClient-0-0] [1s 114ms] Http1Exchange SocketTube(1) connecting flows
14:02:34.343 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [1s 114ms] HttpClientImpl(1) next expired: 0
14:02:34.343 DEBUG [SocketTube.connectFlows] - [JdkHttpClient-0-0] [1s 114ms] SocketTube(1) connecting flows
14:02:34.343 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [1s 114ms] HttpClientImpl(1) Next deadline is 3000
14:02:34.344 DEBUG [SocketTube$InternalReadPublisher.subscribe] - [JdkHttpClient-0-0] [1s 114ms] SocketTube(1) read publisher got subscriber
14:02:34.344 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.signalSubscribe] - [JdkHttpClient-0-0] [1s 114ms] SocketTube(1) registering subscribe event
14:02:34.344 DEBUG [SocketTube.debugState] - [JdkHttpClient-0-0] [1s 115ms] SocketTube(1) leaving read.subscribe:  Reading: [ops=0, demand=0, stopped=false], Writing: [ops=0, demand=0]
14:02:34.344 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handleSubscribeEvent] - [HttpClient-1-SelectorManager] [1s 115ms] SocketTube(1) subscribe event raised
14:02:34.344 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-1-SelectorManager] [1s 115ms] SocketTube(1) handling pending subscription for jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber@3dcbec64
14:02:34.344 DEBUG [Http1Exchange$Http1Publisher.subscribe] - [JdkHttpClient-0-0] [1s 115ms] Http1Publisher(SocketTube(1)) got subscriber: SocketTube(1)
14:02:34.344 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-1-SelectorManager] [1s 115ms] SocketTube(1) read demand reset to 0
14:02:34.345 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [JdkHttpClient-0-0] [1s 115ms] SocketTube(1) subscribed for writing
14:02:34.345 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-1-SelectorManager] [1s 115ms] SocketTube(1) calling onSubscribe
14:02:34.345 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.onSubscribe] - [HttpClient-1-SelectorManager] [1s 115ms] Http1AsyncReceiver(SocketTube(1)) Received onSubscribed from upstream
14:02:34.345 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [JdkHttpClient-0-0] [1s 116ms] SocketTube(1) write: registering startSubscription event
14:02:34.345 DEBUG [Http1Exchange.lambda$sendHeadersAsync$4] - [JdkHttpClient-0-0] [1s 116ms] Http1Exchange requestAction.headers
14:02:34.345 DEBUG [SocketTube$InternalReadPublisher$ReadSubscription.signalOnSubscribe] - [HttpClient-1-SelectorManager] [1s 116ms] SocketTube(1) onSubscribe called
14:02:34.345 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-1-SelectorManager] [1s 116ms] SocketTube(1) pending subscriber subscribed
14:02:34.345 DEBUG [Http1AsyncReceiver.hasDemand] - [JdkHttpClient-0-1] [1s 116ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 1
14:02:34.345 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [1s 116ms] HttpClientImpl(1) next timeout: 299893
14:02:34.346 DEBUG [Http1AsyncReceiver.checkRequestMore] - [JdkHttpClient-0-1] [1s 116ms] Http1AsyncReceiver(SocketTube(1)) checkRequestMore: canRequestMore=true, hasDemand=true
14:02:34.346 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [1s 116ms] HttpClientImpl(1) next expired: 0
14:02:34.346 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.requestMore] - [JdkHttpClient-0-1] [1s 116ms] Http1AsyncReceiver(SocketTube(1)) Http1TubeSubscriber: requesting one more from upstream
14:02:34.346 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [1s 116ms] HttpClientImpl(1) Next deadline is 3000
14:02:34.346 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.request] - [JdkHttpClient-0-1] [1s 116ms] SocketTube(1) got some demand for reading
14:02:34.346 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-1-SelectorManager] [1s 117ms] SocketTube(1) write: starting subscription
14:02:34.346 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [JdkHttpClient-0-1] [1s 117ms] SocketTube(1) resuming read event
14:02:34.346 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-1-SelectorManager] [1s 117ms] SocketTube(1) write: offloading requestMore
14:02:34.347 DEBUG [SocketTube.debugState] - [JdkHttpClient-0-1] [1s 117ms] SocketTube(1) leaving request(1):  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=0]
14:02:34.347 DEBUG [Http1Exchange.lambda$sendHeadersAsync$4] - [JdkHttpClient-0-0] [1s 117ms] Http1Exchange setting outgoing with headers
14:02:34.347 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [1s 117ms] HttpClientImpl(1) next timeout: 299891
14:02:34.347 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [1s 118ms] HttpClientImpl(1) next expired: 0
14:02:34.347 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [JdkHttpClient-0-2] [1s 118ms] SocketTube(1) write: requesting more...
14:02:34.347 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [1s 118ms] HttpClientImpl(1) Next deadline is 3000
14:02:34.347 DEBUG [Http1Exchange.appendToOutgoing] - [JdkHttpClient-0-0] [1s 118ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=337 cap=337]], throwable=null]
14:02:34.347 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-1-SelectorManager] [1s 118ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@4a9babe3 for 1 (true)
14:02:34.347 DEBUG [Http1Exchange$Http1Publisher$Http1WriteSubscription.request] - [JdkHttpClient-0-2] [1s 118ms] Http1Publisher(SocketTube(1)) subscription request(1), demand=1
14:02:34.347 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [1s 118ms] HttpClientImpl(1) next timeout: 299891
14:02:34.347 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [JdkHttpClient-0-0] [1s 118ms] Http1Publisher(SocketTube(1)) WriteTask
14:02:34.348 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [1s 118ms] HttpClientImpl(1) next expired: 0
14:02:34.348 DEBUG [SocketTube.debugState] - [JdkHttpClient-0-2] [1s 118ms] SocketTube(1) leaving requestMore:  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
14:02:34.348 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [1s 118ms] HttpClientImpl(1) Next deadline is 3000
14:02:34.348 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [JdkHttpClient-0-0] [1s 119ms] Http1Publisher(SocketTube(1)) hasOutgoing = true
14:02:34.419 DEBUG [Http1Exchange.getOutgoing] - [JdkHttpClient-0-0] [1s 189ms] Http1Exchange initiating completion of headersSentCF
14:02:34.420 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [JdkHttpClient-0-0] [1s 190ms] Http1Publisher(SocketTube(1)) onNext with 337 bytes
14:02:34.420 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [JdkHttpClient-0-0] [1s 191ms] SocketTube(1) trying to write: 337
14:02:34.420 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [JdkHttpClient-0-0] [1s 191ms] SocketTube(1) wrote: 337
14:02:34.421 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [JdkHttpClient-0-0] [1s 191ms] SocketTube(1) write: requesting more...
14:02:34.421 DEBUG [Http1Exchange$Http1Publisher$Http1WriteSubscription.request] - [JdkHttpClient-0-0] [1s 191ms] Http1Publisher(SocketTube(1)) subscription request(1), demand=1
14:02:34.421 DEBUG [SocketTube.debugState] - [JdkHttpClient-0-0] [1s 191ms] SocketTube(1) leaving requestMore:  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
14:02:34.421 DEBUG [SocketTube.debugState] - [JdkHttpClient-0-0] [1s 192ms] SocketTube(1) leaving w.onNext Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
14:02:34.421 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [JdkHttpClient-0-0] [1s 192ms] Http1Publisher(SocketTube(1)) WriteTask
14:02:34.421 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [JdkHttpClient-0-0] [1s 192ms] Http1Publisher(SocketTube(1)) hasOutgoing = false
14:02:34.421 DEBUG [Exchange.checkFor407] - [JdkHttpClient-0-0] [1s 192ms] Exchange checkFor407: all clear
14:02:34.421 DEBUG [Exchange.sendRequestBody] - [JdkHttpClient-0-0] [1s 192ms] Exchange sendRequestBody
14:02:34.421 DEBUG [Http1Exchange.sendBodyAsync] - [JdkHttpClient-0-0] [1s 192ms] Http1Exchange sendBodyAsync
14:02:34.423 DEBUG [Http1Exchange.sendBodyAsync] - [JdkHttpClient-0-0] [1s 194ms] Http1Exchange bodySubscriber is class jdk.internal.net.http.Http1Request$FixedContentSubscriber
14:02:34.424 DEBUG [Http1Exchange.requestMoreBody] - [JdkHttpClient-0-0] [1s 194ms] Http1Exchange requesting more request body from the subscriber
14:02:34.424 DEBUG [Http1Exchange$Http1BodySubscriber.request] - [JdkHttpClient-0-0] [1s 194ms] jdk.internal.net.http.Http1Request@3254f1f6 Http1BodySubscriber requesting 1, from jdk.internal.net.http.PullPublisher$Subscription@48e4983d
14:02:34.424 DEBUG [Http1Request$FixedContentSubscriber.onNext] - [JdkHttpClient-0-0] [1s 195ms] jdk.internal.net.http.Http1Request@3254f1f6 onNext
14:02:34.424 DEBUG [Http1Exchange.appendToOutgoing] - [JdkHttpClient-0-0] [1s 195ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=517 cap=16384]], throwable=null]
14:02:34.424 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [JdkHttpClient-0-0] [1s 195ms] Http1Publisher(SocketTube(1)) WriteTask
14:02:34.424 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [JdkHttpClient-0-0] [1s 195ms] Http1Publisher(SocketTube(1)) hasOutgoing = true
14:02:34.425 DEBUG [Http1Exchange.requestMoreBody] - [JdkHttpClient-0-0] [1s 195ms] Http1Exchange requesting more request body from the subscriber
14:02:34.425 DEBUG [Http1Exchange$Http1BodySubscriber.request] - [JdkHttpClient-0-0] [1s 195ms] jdk.internal.net.http.Http1Request@3254f1f6 Http1BodySubscriber requesting 1, from jdk.internal.net.http.PullPublisher$Subscription@48e4983d
14:02:34.425 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [JdkHttpClient-0-0] [1s 195ms] Http1Publisher(SocketTube(1)) onNext with 517 bytes
14:02:34.425 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [JdkHttpClient-0-0] [1s 195ms] SocketTube(1) trying to write: 517
14:02:34.425 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [JdkHttpClient-0-0] [1s 196ms] SocketTube(1) wrote: 517
14:02:34.425 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [JdkHttpClient-0-0] [1s 196ms] SocketTube(1) write: requesting more...
14:02:34.425 DEBUG [Http1Exchange$Http1Publisher$Http1WriteSubscription.request] - [JdkHttpClient-0-0] [1s 196ms] Http1Publisher(SocketTube(1)) subscription request(1), demand=1
14:02:34.425 DEBUG [SocketTube.debugState] - [JdkHttpClient-0-0] [1s 196ms] SocketTube(1) leaving requestMore:  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
14:02:34.425 DEBUG [SocketTube.debugState] - [JdkHttpClient-0-0] [1s 196ms] SocketTube(1) leaving w.onNext Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
14:02:34.425 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [JdkHttpClient-0-0] [1s 196ms] Http1Publisher(SocketTube(1)) WriteTask
14:02:34.425 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [JdkHttpClient-0-0] [1s 196ms] Http1Publisher(SocketTube(1)) hasOutgoing = false
14:02:34.425 DEBUG [Http1Request$FixedContentSubscriber.onComplete] - [JdkHttpClient-0-0] [1s 196ms] jdk.internal.net.http.Http1Request@3254f1f6 onComplete
14:02:34.426 DEBUG [Http1Exchange.appendToOutgoing] - [JdkHttpClient-0-0] [1s 196ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=0 cap=0]], throwable=null]
14:02:34.426 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [JdkHttpClient-0-0] [1s 196ms] Http1Publisher(SocketTube(1)) WriteTask
14:02:34.426 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [JdkHttpClient-0-0] [1s 196ms] Http1Publisher(SocketTube(1)) hasOutgoing = true
14:02:34.426 DEBUG [Http1Exchange.getOutgoing] - [JdkHttpClient-0-0] [1s 196ms] Http1Exchange initiating completion of bodySentCF
14:02:34.426 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [JdkHttpClient-0-0] [1s 197ms] Http1Publisher(SocketTube(1)) completed, stopping jdk.internal.net.http.common.SequentialScheduler@b87e24c
14:02:34.426 DEBUG [Utils.lambda$wrapForDebug$9] - [JdkHttpClient-0-0] [1s 197ms] Http1Exchange sendBodyAsync completed successfully
14:02:34.427 DEBUG [Http1Exchange.getResponseAsync] - [JdkHttpClient-0-0] [1s 197ms] Http1Exchange reading headers
14:02:34.429 DEBUG [Http1Response.readHeadersAsync] - [JdkHttpClient-0-0] [1s 200ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) Reading Headers: (remaining: 0) READING_HEADERS
14:02:34.429 DEBUG [Http1Response.readHeadersAsync] - [JdkHttpClient-0-0] [1s 200ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) First time around
14:02:34.429 DEBUG [Http1Response.readHeadersAsync] - [JdkHttpClient-0-0] [1s 200ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) headersReader is not yet completed
14:02:37.351 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [4s 122ms] HttpClientImpl(1) next timeout: 296887
14:02:37.352 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [4s 122ms] HttpClientImpl(1) next expired: 0
14:02:37.352 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [4s 122ms] HttpClientImpl(1) Next deadline is 3000
14:02:40.355 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [7s 125ms] HttpClientImpl(1) next timeout: 293883
14:02:40.355 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [7s 126ms] HttpClientImpl(1) next expired: 0
14:02:40.355 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [7s 126ms] HttpClientImpl(1) Next deadline is 3000
14:02:43.359 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [10s 129ms] HttpClientImpl(1) next timeout: 290879
14:02:43.359 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [10s 130ms] HttpClientImpl(1) next expired: 0
14:02:43.359 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [10s 130ms] HttpClientImpl(1) Next deadline is 3000
14:02:46.361 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [13s 132ms] HttpClientImpl(1) next timeout: 287877
14:02:46.362 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [13s 132ms] HttpClientImpl(1) next expired: 0
14:02:46.362 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [13s 132ms] HttpClientImpl(1) Next deadline is 3000
14:02:49.365 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [16s 136ms] HttpClientImpl(1) next timeout: 284873
14:02:49.365 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [16s 136ms] HttpClientImpl(1) next expired: 0
14:02:49.365 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [16s 136ms] HttpClientImpl(1) Next deadline is 3000
14:02:52.369 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [19s 139ms] HttpClientImpl(1) next timeout: 281869
14:02:52.369 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [19s 140ms] HttpClientImpl(1) next expired: 0
14:02:52.369 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [19s 140ms] HttpClientImpl(1) Next deadline is 3000
14:02:55.372 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [22s 143ms] HttpClientImpl(1) next timeout: 278866
14:02:55.373 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [22s 143ms] HttpClientImpl(1) next expired: 0
14:02:55.373 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [22s 143ms] HttpClientImpl(1) Next deadline is 3000
14:02:58.374 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [25s 144ms] HttpClientImpl(1) next timeout: 275864
14:02:58.374 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [25s 145ms] HttpClientImpl(1) next expired: 0
14:02:58.374 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [25s 145ms] HttpClientImpl(1) Next deadline is 3000
14:03:01.422 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [28s 192ms] HttpClientImpl(1) next timeout: 272817
14:03:01.422 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [28s 192ms] HttpClientImpl(1) next expired: 0
14:03:01.422 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [28s 192ms] HttpClientImpl(1) Next deadline is 3000
14:03:04.424 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [31s 195ms] HttpClientImpl(1) next timeout: 269814
14:03:04.425 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [31s 196ms] HttpClientImpl(1) next expired: 0
14:03:04.425 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [31s 196ms] HttpClientImpl(1) Next deadline is 3000
14:03:07.428 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [34s 199ms] HttpClientImpl(1) next timeout: 266810
14:03:07.429 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [34s 199ms] HttpClientImpl(1) next expired: 0
14:03:07.429 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [34s 199ms] HttpClientImpl(1) Next deadline is 3000
14:03:10.431 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [37s 202ms] HttpClientImpl(1) next timeout: 263807
14:03:10.432 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [37s 202ms] HttpClientImpl(1) next expired: 0
14:03:10.432 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [37s 202ms] HttpClientImpl(1) Next deadline is 3000
14:03:13.434 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [40s 205ms] HttpClientImpl(1) next timeout: 260804
14:03:13.435 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [40s 205ms] HttpClientImpl(1) next expired: 0
14:03:13.435 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [40s 205ms] HttpClientImpl(1) Next deadline is 3000
14:03:16.438 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [43s 209ms] HttpClientImpl(1) next timeout: 257800
14:03:16.439 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [43s 209ms] HttpClientImpl(1) next expired: 0
14:03:16.439 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [43s 209ms] HttpClientImpl(1) Next deadline is 3000
14:03:19.439 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [46s 210ms] HttpClientImpl(1) next timeout: 254799
14:03:19.440 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [46s 210ms] HttpClientImpl(1) next expired: 0
14:03:19.440 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [46s 210ms] HttpClientImpl(1) Next deadline is 3000
14:03:22.443 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [49s 214ms] HttpClientImpl(1) next timeout: 251795
14:03:22.443 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [49s 214ms] HttpClientImpl(1) next expired: 0
14:03:22.443 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [49s 214ms] HttpClientImpl(1) Next deadline is 3000
14:03:25.447 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [52s 217ms] HttpClientImpl(1) next timeout: 248791
14:03:25.518 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [52s 289ms] HttpClientImpl(1) next expired: 0
14:03:25.519 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [52s 289ms] HttpClientImpl(1) Next deadline is 3000
14:03:28.521 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [55s 292ms] HttpClientImpl(1) next timeout: 245717
14:03:28.522 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [55s 292ms] HttpClientImpl(1) next expired: 0
14:03:28.522 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [55s 292ms] HttpClientImpl(1) Next deadline is 3000
14:03:31.525 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [58s 296ms] HttpClientImpl(1) next timeout: 242713
14:03:31.525 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [58s 296ms] HttpClientImpl(1) next expired: 0
14:03:31.526 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [58s 296ms] HttpClientImpl(1) Next deadline is 3000
2024-07-25 14:03:34,529 INFO reaped unknown pid 1137 (exit status 0)
2024-07-25 14:03:34,529 INFO reaped unknown pid 1139 (exit status 0)
14:03:34.528 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [61s 299ms] HttpClientImpl(1) next timeout: 239710
14:03:34.529 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [61s 299ms] HttpClientImpl(1) next expired: 0
14:03:34.529 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [61s 300ms] HttpClientImpl(1) Next deadline is 3000
14:03:34.531 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-1-SelectorManager] [61s 301ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@4a9babe3 for 0 (false)
14:03:34.533 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-1-SelectorManager] [61s 304ms] SocketTube(1) read bytes: 979
14:03:34.533 DEBUG [Http1AsyncReceiver.asyncReceive] - [HttpClient-1-SelectorManager] [61s 304ms] Http1AsyncReceiver(SocketTube(1)) Putting 979 bytes into the queue
14:03:34.534 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [HttpClient-1-SelectorManager] [61s 304ms] SocketTube(1) resuming read event
14:03:34.534 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-1-SelectorManager] [61s 305ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@4a9babe3 for 1 (false)
14:03:34.534 DEBUG [Http1AsyncReceiver.flush] - [JdkHttpClient-0-3] [61s 305ms] Http1AsyncReceiver(SocketTube(1)) Got 979 bytes for delegate jdk.internal.net.http.Http1Response$HeadersReader@4e11497
14:03:34.534 DEBUG [Http1AsyncReceiver.hasDemand] - [JdkHttpClient-0-3] [61s 305ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 1
14:03:34.534 DEBUG [Http1AsyncReceiver.flush] - [JdkHttpClient-0-3] [61s 305ms] Http1AsyncReceiver(SocketTube(1)) Forwarding 979 bytes to delegate jdk.internal.net.http.Http1Response$HeadersReader@4e11497
14:03:34.534 DEBUG [SocketTube.debugState] - [HttpClient-1-SelectorManager] [61s 305ms] SocketTube(1) leaving read() loop after onNext:  Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
14:03:34.535 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [61s 305ms] HttpClientImpl(1) next timeout: 239703
14:03:34.535 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [61s 305ms] HttpClientImpl(1) next expired: 0
14:03:34.535 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [61s 305ms] HttpClientImpl(1) Next deadline is 3000
14:03:34.537 DEBUG [Http1Response$HeadersReader.handle] - [JdkHttpClient-0-3] [61s 307ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) Sending 979/979 bytes to header parser
14:03:34.538 DEBUG [Http1Response$HeadersReader.handle] - [JdkHttpClient-0-3] [61s 308ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) Parsing headers completed. bytes=128
14:03:34.538 DEBUG [Http1AsyncReceiver.unsubscribe] - [JdkHttpClient-0-3] [61s 309ms] Http1AsyncReceiver(SocketTube(1)) Unsubscribed jdk.internal.net.http.Http1Response$HeadersReader@4e11497
14:03:34.538 DEBUG [Http1Response.lambda$readHeadersAsync$0] - [JdkHttpClient-0-3] [61s 309ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) Reading Headers: creating Response object; state is now READING_BODY
14:03:34.538 DEBUG [Utils.lambda$wrapForDebug$9] - [JdkHttpClient-0-3] [61s 309ms] Http1Exchange getResponseAsync completed successfully
14:03:34.540 DEBUG [Http1Response.readBody] - [JdkHttpClient-0-3] [61s 311ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) readBody: return2Cache: true
14:03:34.625 DEBUG [Http1Response$ClientRefCountTracker.acquire] - [JdkHttpClient-0-3] [61s 396ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) Operation started: incrementing ref count for jdk.internal.net.http.HttpClientImpl@17feca88(1)
14:03:34.627 DEBUG [Http1AsyncReceiver.subscribe] - [JdkHttpClient-0-3] [61s 397ms] Http1AsyncReceiver(SocketTube(1)) Subscribed pending jdk.internal.net.http.Http1Response$BodyReader@455fa93f/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@657c5406 queue.isEmpty: false
14:03:34.632 DEBUG [Http1AsyncReceiver.flush] - [JdkHttpClient-0-3] [61s 403ms] Http1AsyncReceiver(SocketTube(1)) Delegate done: 851
14:03:34.632 DEBUG [ResponseContent$FixedLengthBodyParser.onSubscribe] - [JdkHttpClient-0-3] [61s 403ms] PlainHttpConnection(SocketTube(1))/ResponseContent/FixedLengthBodyParser length=851, onSubscribe: jdk.internal.net.http.Http1Response$Http1BodySubscriber
14:03:34.633 DEBUG [Http1AsyncReceiver.handlePendingDelegate] - [JdkHttpClient-0-3] [61s 403ms] Http1AsyncReceiver(SocketTube(1)) delegate is now jdk.internal.net.http.Http1Response$BodyReader@455fa93f/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@657c5406, demand=9223372036854775807, canRequestMore=false, queue.isEmpty=false
14:03:34.633 DEBUG [Http1AsyncReceiver.flush] - [JdkHttpClient-0-3] [61s 403ms] Http1AsyncReceiver(SocketTube(1)) Got 851 bytes for delegate jdk.internal.net.http.Http1Response$BodyReader@455fa93f/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@657c5406
14:03:34.633 DEBUG [Http1AsyncReceiver.hasDemand] - [JdkHttpClient-0-3] [61s 403ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 9223372036854775807
14:03:34.633 DEBUG [Http1AsyncReceiver.flush] - [JdkHttpClient-0-3] [61s 403ms] Http1AsyncReceiver(SocketTube(1)) Forwarding 851 bytes to delegate jdk.internal.net.http.Http1Response$BodyReader@455fa93f/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@657c5406
14:03:34.633 DEBUG [Http1Response$BodyReader.handle] - [JdkHttpClient-0-3] [61s 404ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) Sending 851/979 bytes to body parser
14:03:34.633 DEBUG [ResponseContent$FixedLengthBodyParser.accept] - [JdkHttpClient-0-3] [61s 404ms] PlainHttpConnection(SocketTube(1))/ResponseContent/FixedLengthBodyParser Parser got 851 bytes (851 remaining / 851)
14:03:34.633 DEBUG [ResponseContent$FixedLengthBodyParser.accept] - [JdkHttpClient-0-3] [61s 404ms] PlainHttpConnection(SocketTube(1))/ResponseContent/FixedLengthBodyParser Parser got all expected bytes: completing
14:03:34.633 DEBUG [Http1AsyncReceiver.clear] - [JdkHttpClient-0-3] [61s 404ms] Http1AsyncReceiver(SocketTube(1)) cleared
14:03:34.633 DEBUG [Http1Response.onFinished] - [JdkHttpClient-0-3] [61s 404ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) SocketTube(1): return to HTTP/1.1 pool
14:03:34.634 DEBUG [ConnectionPool.registerCleanupTrigger] - [JdkHttpClient-0-3] [61s 405ms] ConnectionPool(1) registering CleanupTrigger(SocketTube(1))
14:03:34.635 DEBUG [SocketTube.connectFlows] - [JdkHttpClient-0-3] [61s 405ms] SocketTube(1) connecting flows
14:03:34.635 DEBUG [SocketTube$InternalReadPublisher.subscribe] - [JdkHttpClient-0-3] [61s 405ms] SocketTube(1) read publisher got subscriber
14:03:34.635 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.signalSubscribe] - [JdkHttpClient-0-3] [61s 405ms] SocketTube(1) registering subscribe event
14:03:34.635 DEBUG [SocketTube.debugState] - [JdkHttpClient-0-3] [61s 405ms] SocketTube(1) leaving read.subscribe:  Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
14:03:34.635 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [JdkHttpClient-0-3] [61s 405ms] SocketTube(1) subscribed for writing
14:03:34.635 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.dropSubscription] - [JdkHttpClient-0-3] [61s 405ms] SocketTube(1) write: resetting demand to 0
14:03:34.635 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [JdkHttpClient-0-3] [61s 405ms] SocketTube(1) write: registering startSubscription event
14:03:34.635 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handleSubscribeEvent] - [HttpClient-1-SelectorManager] [61s 406ms] SocketTube(1) subscribe event raised
14:03:34.635 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-1-SelectorManager] [61s 406ms] SocketTube(1) handling pending subscription for CleanupTrigger(SocketTube(1))
14:03:34.635 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.dropSubscription] - [HttpClient-1-SelectorManager] [61s 406ms] Http1AsyncReceiver(SocketTube(1)) Http1TubeSubscriber: dropSubscription
14:03:34.635 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-1-SelectorManager] [61s 406ms] SocketTube(1) read demand reset to 0
14:03:34.635 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-1-SelectorManager] [61s 406ms] SocketTube(1) calling onSubscribe
14:03:34.636 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.request] - [HttpClient-1-SelectorManager] [61s 406ms] SocketTube(1) got some demand for reading
14:03:34.636 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [HttpClient-1-SelectorManager] [61s 406ms] SocketTube(1) resuming read event
14:03:34.636 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-1-SelectorManager] [61s 406ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@4a9babe3 for 1 (false)
14:03:34.636 DEBUG [SocketTube.debugState] - [HttpClient-1-SelectorManager] [61s 406ms] SocketTube(1) leaving request(1):  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=0]
14:03:34.636 DEBUG [SocketTube$InternalReadPublisher$ReadSubscription.signalOnSubscribe] - [HttpClient-1-SelectorManager] [61s 406ms] SocketTube(1) onSubscribe called
14:03:34.636 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-1-SelectorManager] [61s 406ms] SocketTube(1) pending subscriber subscribed
14:03:34.636 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-1-SelectorManager] [61s 406ms] SocketTube(1) write: starting subscription
14:03:34.636 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-1-SelectorManager] [61s 407ms] SocketTube(1) write: offloading requestMore
14:03:34.637 DEBUG [Http1Response.lambda$readBody$2] - [JdkHttpClient-0-3] [61s 407ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) Finished reading body: READING_BODY
14:03:34.637 DEBUG [Http1Response$ClientRefCountTracker.tryRelease] - [JdkHttpClient-0-3] [61s 407ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) Operation finished: decrementing ref count for jdk.internal.net.http.HttpClientImpl@17feca88(1)
14:03:34.637 DEBUG [Http1AsyncReceiver.flush] - [JdkHttpClient-0-3] [61s 407ms] Http1AsyncReceiver(SocketTube(1)) Delegate done: 0
14:03:34.637 DEBUG [Http1AsyncReceiver.flush] - [JdkHttpClient-0-3] [61s 408ms] Http1AsyncReceiver(SocketTube(1)) Got 0 bytes for delegate null
14:03:34.719 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [61s 489ms] HttpClientImpl(1) next timeout: 0
14:03:34.719 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [JdkHttpClient-0-4] [61s 489ms] SocketTube(1) write: requesting more...
14:03:34.719 DEBUG [SocketTube.debugState] - [JdkHttpClient-0-4] [61s 490ms] SocketTube(1) leaving requestMore:  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
14:03:34.719 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [61s 490ms] HttpClientImpl(1) next expired: 1199281
14:03:34.719 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [61s 490ms] HttpClientImpl(1) Next deadline is 3000
14:03:34.720 DEBUG [JdkHttpClient.execute0] - Ending request (POST) /session in 60,500ms
14:03:34.720 DEBUG [SeleniumSpanExporter$1.lambda$export$4] - SpanData{spanContext=ImmutableSpanContext{traceId=2d3268b08dce473e96c11409c2b93ebd, spanId=33df51c01f0fb489, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=2d3268b08dce473e96c11409c2b93ebd, spanId=7a92a0c36fb55c2f, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, resource=Resource{schemaUrl=null, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.40.0"}}, instrumentationScopeInfo=InstrumentationScopeInfo{name=default, version=null, schemaUrl=null, attributes={}}, name=httpclient.execute, kind=INTERNAL, startEpochNanos=1721916154219189451, endEpochNanos=1721916214720841713, attributes=AttributesMap{data={span.kind=client, http.target=/session, http.status_code=500, http.method=POST}, capacity=128, totalAddedValues=4}, totalAttributeCount=4, events=[], totalRecordedEvents=0, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=ERROR, description=Kind: INTERNAL Description:}, hasEnded=true}
14:03:34.725 WARN [DriverServiceSessionFactory.apply] - Error while creating session with the driver service. Stopping driver service: Could not start a new session. Response code 500. Message: session not created: DevToolsActivePort file doesn't exist
Host info: host: 'selenium-grid-4-test-node-227-dqqgk', ip: '10.254.22.39'
Build info: version: '4.23.0', revision: '4df0a231af'
System info: os.name: 'Linux', os.arch: 'amd64', os.version: '4.18.0-372.96.1.el8_6.x86_64', java.version: '17.0.11'
Driver info: driver.version: unknown
org.openqa.selenium.SessionNotCreatedException: Could not start a new session. Response code 500. Message: session not created: DevToolsActivePort file doesn't exist
Host info: host: 'selenium-grid-4-test-node-227-dqqgk', ip: '10.254.22.39'
Build info: version: '4.23.0', revision: '4df0a231af'
System info: os.name: 'Linux', os.arch: 'amd64', os.version: '4.18.0-372.96.1.el8_6.x86_64', java.version: '17.0.11'
Driver info: driver.version: unknown
                at org.openqa.selenium.remote.ProtocolHandshake.createSession(ProtocolHandshake.java:114)
                at org.openqa.selenium.remote.ProtocolHandshake.createSession(ProtocolHandshake.java:75)
                at org.openqa.selenium.remote.ProtocolHandshake.createSession(ProtocolHandshake.java:61)
                at org.openqa.selenium.grid.node.config.DriverServiceSessionFactory.apply(DriverServiceSessionFactory.java:161)
                at org.openqa.selenium.grid.node.config.DriverServiceSessionFactory.apply(DriverServiceSessionFactory.java:71)
                at org.openqa.selenium.grid.node.local.SessionSlot.apply(SessionSlot.java:147)
                at org.openqa.selenium.grid.node.local.LocalNode.newSession(LocalNode.java:469)
                at org.openqa.selenium.grid.node.NewNodeSession.execute(NewNodeSession.java:50)
                at org.openqa.selenium.remote.http.Route$TemplatizedRoute.handle(Route.java:192)
                at org.openqa.selenium.remote.http.Route.execute(Route.java:69)
                at org.openqa.selenium.grid.security.RequiresSecretFilter.lambda$apply$0(RequiresSecretFilter.java:62)
                at org.openqa.selenium.remote.tracing.SpanWrappedHttpHandler.execute(SpanWrappedHttpHandler.java:87)
                at org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:63)
                at org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:360)
                at org.openqa.selenium.remote.http.Route.execute(Route.java:69)
                at org.openqa.selenium.grid.node.Node.execute(Node.java:270)
                at org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:360)
                at org.openqa.selenium.remote.http.Route.execute(Route.java:69)
                at org.openqa.selenium.remote.AddWebDriverSpecHeaders.lambda$apply$0(AddWebDriverSpecHeaders.java:35)
                at org.openqa.selenium.remote.ErrorFilter.lambda$apply$0(ErrorFilter.java:44)
                at org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:63)
                at org.openqa.selenium.remote.ErrorFilter.lambda$apply$0(ErrorFilter.java:44)
                at org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:63)
                at org.openqa.selenium.netty.server.SeleniumHandler.lambda$channelRead0$0(SeleniumHandler.java:44)
                at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
                at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
                at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
                at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
                at java.base/java.lang.Thread.run(Thread.java:842)
14:03:34.726 DEBUG [UrlChecker.waitUntilUnavailable] - Waiting for http://localhost:18350/shutdown
14:03:34.726 DEBUG [UrlChecker.lambda$waitUntilUnavailable$2] - Polling http://localhost:18350/shutdown
14:03:34.727 FINEST [HttpURLConnection.plainConnect0] - ProxySelector Request for http://localhost:18350/shutdown
14:03:34.727 FINEST [HttpURLConnection.plainConnect0] - Proxy used: DIRECT
14:03:34.728 DEBUG [HttpURLConnection.writeRequests] - sun.net.www.MessageHeader@70a5e79b5 pairs: {GET /shutdown HTTP/1.1: null}{User-Agent: Java/17.0.11}{Host: localhost:18350}{Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2}{Connection: keep-alive}
14:03:34.728 FINEST [HttpClient.logFinest] - KeepAlive stream used: http://localhost:18350/shutdown
14:03:34.728 DEBUG [HttpURLConnection.getInputStream0] - sun.net.www.MessageHeader@7e6207ff3 pairs: {null: HTTP/1.1 200 OK}{Content-Length: 40}{Content-Type: application/json; charset=utf-8}
14:03:34.728 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-1-SelectorManager] [61s 499ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@4a9babe3 for 0 (false)
14:03:34.729 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-1-SelectorManager] [61s 499ms] SocketTube(1) got read EOF
14:03:34.729 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.pauseReadEvent] - [HttpClient-1-SelectorManager] [61s 499ms] SocketTube(1) pausing read event
14:03:34.729 FINEST [ClientVector.get] - cached HttpClient was idle for 0
14:03:34.729 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-1-SelectorManager] [61s 500ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@4a9babe3 for 0 (false)
14:03:34.729 DEBUG [SocketTube$InternalReadPublisher$ReadSubscription.signalCompletion] - [HttpClient-1-SelectorManager] [61s 500ms] SocketTube(1) completing subscriber
14:03:34.729 DEBUG [ConnectionPool.cleanup] - [HttpClient-1-SelectorManager] [61s 500ms] ConnectionPool(1) SocketTube(1) : ConnectionPool.cleanup(null)
14:03:34.730 DEBUG [PlainHttpConnection.close] - [HttpClient-1-SelectorManager] [61s 500ms] PlainHttpConnection(SocketTube(1)) Closing channel: channel registered with selector, key.interestOps=1, sa.interestOps=1
14:03:34.730 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.signalError] - [HttpClient-1-SelectorManager] [61s 501ms] SocketTube(1) signal read error: java.io.IOException: connection closed locally
14:03:34.730 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.signalError] - [HttpClient-1-SelectorManager] [61s 501ms] SocketTube(1) got read error: java.io.IOException: connection closed locally
14:03:34.730 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-1-SelectorManager] [61s 501ms] SocketTube(1) Stopping read scheduler
14:03:34.730 DEBUG [SocketTube.debugState] - [HttpClient-1-SelectorManager] [61s 501ms] SocketTube(1) leaving read() loop after EOF:  Reading: [ops=0, demand=0, stopped=true], Writing: [ops=0, demand=1]
14:03:34.730 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-1-SelectorManager] [61s 501ms] SocketTube(1) Read scheduler stopped
14:03:34.730 DEBUG [HttpClientImpl$SelectorAttachment.resetInterestOps] - [HttpClient-1-SelectorManager] [61s 501ms] SelectorAttachment key cancelled for java.nio.channels.SocketChannel[closed]
14:03:34.731 DEBUG [SocketTube$SocketFlowEvent.abort] - [HttpClient-1-SelectorManager] [61s 502ms] SocketTube(1) ReadEvent abort: java.io.IOException: java.nio.channels.CancelledKeyException
14:03:34.731 DEBUG [SocketTube$InternalReadPublisher$ReadEvent.signalError] - [HttpClient-1-SelectorManager] [61s 502ms] SocketTube(1) signalError to jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription@5dcd88e4 (java.io.IOException: java.nio.channels.CancelledKeyException)
14:03:34.731 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.signalError] - [HttpClient-1-SelectorManager] [61s 502ms] SocketTube(1) signal read error: java.io.IOException: java.nio.channels.CancelledKeyException
14:03:34.731 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [61s 502ms] HttpClientImpl(1) next timeout: 0
14:03:34.731 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [61s 502ms] HttpClientImpl(1) next expired: 0
14:03:34.731 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [61s 502ms] HttpClientImpl(1) Next deadline is 3000
14:03:34.739 DEBUG [UrlChecker.lambda$waitUntilUnavailable$2] - Polling http://localhost:18350/shutdown
14:03:34.739 FINEST [HttpURLConnection.plainConnect0] - ProxySelector Request for http://localhost:18350/shutdown
14:03:36.019 DEBUG [LoggingHandler.channelRead] - [id: 0x52e4efc2, L:/[0:0:0:0:0:0:0:0]:5555] READ: [id: 0xe40b3f40, L:/10.254.22.39:5555 - R:/10.254.23.87:41558]
14:03:36.019 DEBUG [LoggingHandler.channelReadComplete] - [id: 0x52e4efc2, L:/[0:0:0:0:0:0:0:0]:5555] READ COMPLETE
14:03:36.026 DEBUG [RequestConverter.channelRead0] - Incoming message: DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)

Operating System

RedHat 8

Selenium version

4.23.0

What are the browser(s) and version(s) where you see this issue?

N/A

What are the browser driver(s) and version(s) where you see this issue?

N/A

Are you using Selenium Grid?

4.23.0

github-actions[bot] commented 3 months ago

@KrzysztofC, thank you for creating this issue. We will troubleshoot it as soon as we can.

Info for maintainers

Triage this issue by using labels.

If information is missing, add a helpful comment and then I-issue-template label.

If the issue is a question, add the I-question label.

If the issue is valid but there is no time to troubleshoot it, consider adding the help wanted label.

If the issue requires changes or fixes from an external project (e.g., ChromeDriver, GeckoDriver, MSEdgeDriver, W3C), add the applicable G-* label, and it will provide the correct link and auto-close the issue.

After troubleshooting the issue, please add the R-awaiting answer label.

Thank you!

joerg1985 commented 3 months ago

I think this is a webdriver related issue. The selenium node does start the driver and the driver starts the browser. When the browser does not start in time the driver does raise this error.

VietND96 commented 3 months ago

Host info: host: 'selenium-grid-4-test-node-227-dqqgk', ip: '10.254.22.39' 14:03:34.720 DEBUG [JdkHttpClient.execute0] - Ending request (POST) /session in 60,500ms

Looks like you are running Grid on K8s env. So I think you need to check this thing. Does the setup have an ingress proxy in front? If yes, what read-timeout is set there?

KrzysztofC commented 3 months ago

My route in OpenShift already has haproxy.router.openshift.io/timeout set to a higher value of 365s according to https://docs.openshift.com/container-platform/4.16/networking/routes/route-configuration.html My tests capture me time stamps before and after WebDriver driver command and calculate duration to create session. I have seen in the past session taking longer than 2 minutes to get created without any errors in the same env, but I can't explain why/how that worked and when was the last time it worked. Things that changed since then were: updating selenium jar to latest, updating Chrome/chromedriver to latest and possibly it was before I moved from JDK11 to JDK17.

diemol commented 3 months ago

Does the issue happen when there are low resources?

KrzysztofC commented 3 months ago

Container is dedicated to running selenium node and browser, nothing else. 8GB Ram allocated and 1 CPU allocated. I think it is pure timing thing, due to slowness. It can be replicated by allocating less CPU, below a point where browser takes more than 60 seconds to start and "fixed" by allocating more CPU resources where browser takes less than 60 seconds to start. Resources (especially CPUs) are quite expensive in our environment. I have tried JDK21 but it's the same, I'm currently running with JDK17.

diemol commented 3 months ago

That's a lot of RAM and too little CPU. Browsers have peaks and might go over 1 CPU. You usually need to have a few free CPUs to handle those peaks.

KrzysztofC commented 3 months ago

I understand, but this is openshift, each container runs on an App Node with multiple CPUs visible to it, the CPU setting really controls overall speed with some scheduling, not number of CPUs or threads available. We run 100 Grid Nodes 1 browser each, so it's not possible to go from 1 CPU to multiple on entire setup. It would be ideal if the --session-request-timeout timeout would work with anything higher than 60 seconds, because once the browser opens, thousands of tests run without issues and cpu load stays well below 50% most of the time in those containers. We are trying to be as efficient as possible with limited resources we have. I also checked chromedriver but it does not appear to have any params related to timeouts. I was thinking to create an Image with older selenium, JDK11 and older browser/driver, I will see if I can do that. Old selenium + JDK11 first.

abakre-tibco commented 3 months ago

I get the same when headless is set to true. Works fine with headless as false.

diemol commented 3 months ago

When Grid starts the command to open the browser, it uses the configured sessionRequestTimeout. However, the 60 seconds timeout comes directly from ChromeDriver.

Unfortunately, there is no option to configure that timeout. They assume a browser should open in less than 1 minute.

You can file a bug report with the Chrome folks and/or budget your infrastructure for this situation. For example, instead of 100 browsers with 100 CPUs, you should probably run just 90 browsers and keep tuning the value until you find a stable configuration.

github-actions[bot] commented 3 months ago

Hi, @KrzysztofC. This issue has been determined to require fixes in ChromeDriver.

You can see if the feature is passing in the Web Platform Tests.

If it is something new, please create an issue with the ChromeDriver team. Feel free to comment the issues that you raise back in this issue. Thank you.

abakre-tibco commented 3 months ago

@KrzysztofC Can you check if you have xvfb running on the container executing your tests?. I was able to solve my issue after starting xvfb. With previous Selenium container images, I did not have to start xvfb explicitly but looks like with new version it's required.

nohup /opt/bin/start-xvfb.sh &

nohup ./start-selenium-standalone.sh &
github-actions[bot] commented 2 months ago

This issue has been automatically locked since there has not been any recent activity since it was closed. Please open a new issue for related bugs.