[🐛 Bug]: "Unable to obtain: Capabilities" Version 4.11->4.12.1 #12802
Comments
|
@eravion, thank you for creating this issue. We will troubleshoot it as soon as we can. Info for maintainersTriage this issue by using labels.
If information is missing, add a helpful comment and then
If the issue is a question, add the
If the issue is valid but there is no time to troubleshoot it, consider adding the
If the issue requires changes or fixes from an external project (e.g., ChromeDriver, GeckoDriver, MSEdgeDriver, W3C),
add the applicable
After troubleshooting the issue, please add the Thank you! |
The driver location has not been set by system property or the code, so Selenium Manager is running to try to locate the driver on PATH. For some reason the binary is not getting found in the temp directory. @bonigarcia do you know when this might happen? The temporary fix is to set a system property ( |
|
This error indicated that Selenium Manager has been invoked in offline mode: I suppose chromedriver is not in the PATH (and it cannot be downloaded since offline mode is on), so it is failing. |
|
Although, now I see it is not an error but a warning: Maybe the offline mode is ok, but I am not sure about how Selenium Grid calls Selenium Manager. |
|
So when a node starts, it uses selenium manager to look for drivers on path in offline mode to see what all browsers are available to be supported. Then when the driver class gets initialized and the service needs to be started, it uses selenium manager again to locate what it is going to use. For some reason it was able to use selenium manager on node startup, but unable up use it when trying to start a session. Are you running in parallel? Can you set the logs to debug/fine to see if there is more info on what it is trying to do? |
|
Hello, trace FINE where it is ok |
|
And when it is not OK 08:07:55.309 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [82s 505ms] HttpClientImpl(1) next timeout: 0
08:07:55.309 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [82s 505ms] HttpClientImpl(1) next expired: 0
08:07:55.310 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [82s 505ms] HttpClientImpl(1) Next deadline is 3000
08:07:56.159 DEBUG [RequestConverter.channelRead0] - Incoming message: DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
POST /se/grid/node/session HTTP/1.1
Connection: Upgrade, HTTP2-Settings
Content-Length: 319
Host: 10.237.23.122:5454
HTTP2-Settings: AAEAAEAAAAIAAAABAAMAAABkAAQBAAAAAAUAAEAA
Upgrade: h2c
traceparent: 00-a3c54304740d77c7758dd90c0271af71-dfd6cea1a0f1c158-01
User-Agent: selenium/4.12.1 (java unix)
X-REGISTRATION-SECRET:
08:07:56.159 DEBUG [RequestConverter.channelRead0] - Start of http request: DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
POST /se/grid/node/session HTTP/1.1
Connection: Upgrade, HTTP2-Settings
Content-Length: 319
Host: 10.237.23.122:5454
HTTP2-Settings: AAEAAEAAAAIAAAABAAMAAABkAAQBAAAAAAUAAEAA
Upgrade: h2c
traceparent: 00-a3c54304740d77c7758dd90c0271af71-dfd6cea1a0f1c158-01
User-Agent: selenium/4.12.1 (java unix)
X-REGISTRATION-SECRET:
08:07:56.160 DEBUG [RequestConverter.channelRead0] - Incoming message: DefaultLastHttpContent(data: PooledSlicedByteBuf(ridx: 0, widx: 319, cap: 319/319, unwrapped: PooledUnsafeDirectByteBuf(ridx: 650, widx: 650, cap: 1024)), decoderResult: success)
08:07:56.160 DEBUG [RequestConverter.channelRead0] - End of http request: DefaultLastHttpContent(data: PooledSlicedByteBuf(ridx: 319, widx: 319, cap: 319/319, unwrapped: PooledUnsafeDirectByteBuf(ridx: 650, widx: 650, cap: 1024)), decoderResult: success)
08:07:56.160 DEBUG [SpanWrappedHttpHandler.execute] - Wrapping request. Before OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@fdefd3f, context={}, span id=0000000000000000, trace id=00000000000000000000000000000000} and after OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@fdefd3f, context={opentelemetry-trace-span-key=SdkSpan{traceId=a3c54304740d77c7758dd90c0271af71, spanId=a1f52cc598da6b6a, parentSpanContext=ImmutableSpanContext{traceId=a3c54304740d77c7758dd90c0271af71, spanId=dfd6cea1a0f1c158, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, name=node.new_session, kind=INTERNAL, attributes=AttributesMap{data={random.key=e793e131-1ccb-4046-ab88-194b717a528c}, capacity=128, totalAddedValues=1}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1695629276160000000, endEpochNanos=0}}, span id=a1f52cc598da6b6a, trace id=a3c54304740d77c7758dd90c0271af71}
08:07:56.160 DEBUG [HttpTracing.inject] - Injecting (POST) /se/grid/node/session into OpenTelemetrySpan{traceId=a3c54304740d77c7758dd90c0271af71,spanId=a1f52cc598da6b6a} at org.openqa.selenium.remote.tracing.SpanWrappedHttpHandler:89
08:07:56.174 DEBUG [SeleniumManager.getBinary] - Selenium Manager binary found at: /tmp/selenium-manager162108532811418711256966606420825087/selenium-manager
08:07:56.176 DEBUG [SeleniumManager.runCommand] - Executing Process: [--browser, chrome, --output, json, --debug]
08:07:56.278 DEBUG [SeleniumManager.lambda$runCommand$1] - Found chromedriver 117.0.5938.88 in PATH: /usr/bin/chromedriver
08:07:56.280 DEBUG [SeleniumManager.lambda$runCommand$1] - chrome detected at /opt/google/chrome/google-chrome
08:07:56.280 DEBUG [SeleniumManager.lambda$runCommand$1] - Running command: /opt/google/chrome/google-chrome --version
08:07:56.280 DEBUG [SeleniumManager.lambda$runCommand$1] - Output: "Google Chrome 117.0.5938.88 "
08:07:56.280 DEBUG [SeleniumManager.lambda$runCommand$1] - Detected browser: chrome 117.0.5938.88
08:07:56.280 WARN [SeleniumManager.lambda$runCommand$1] - Exception managing chrome: Unable to discover proper chromedriver version in offline mode
08:07:56.280 DEBUG [SeleniumManager.lambda$runCommand$1] - Driver path: /usr/bin/chromedriver
08:07:56.280 DEBUG [SeleniumManager.lambda$runCommand$1] - Browser path: /opt/google/chrome/google-chrome
08:07:56.280 DEBUG [SeleniumManager.getDriverPath] - Using driver at location: /usr/bin/chromedriver, browser at location /opt/google/chrome/google-chrome
08:07:56.286 DEBUG [DriverService.start] - Starting driver at /usr/bin/chromedriver with [--port=25209]
08:07:56.343 DEBUG [UrlChecker.waitUntilAvailable] - Waiting for [http://localhost:25209/status]
08:07:56.345 DEBUG [UrlChecker.lambda$waitUntilAvailable$1] - Polling http://localhost:25209/status
08:07:56.345 DEBUG [HttpURLConnection.writeRequests] - sun.net.www.MessageHeader@5a22fd865 pairs: {GET /status HTTP/1.1: null}{User-Agent: Java/11.0.20.1}{Host: localhost:25209}{Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2}{Connection: keep-alive}
08:07:56.347 DEBUG [HttpURLConnection.getInputStream0] - sun.net.www.MessageHeader@2625684 pairs: {null: HTTP/1.1 200 OK}{Content-Length: 249}{Content-Type: application/json; charset=utf-8}{cache-control: no-cache}
08:07:56.350 DEBUG [HttpClientImpl.<init>] - [pool-2-thread-1] [83s 545ms] HttpClientImpl(12) proxySelector is sun.net.spi.DefaultProxySelector@19c66617 (user-supplied=false)
08:07:56.358 DEBUG [JdkHttpClient.execute0] - Executing request: (POST) /session
08:07:56.360 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [83s 555ms] HttpClientImpl(12) next timeout: 0
08:07:56.361 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [83s 557ms] HttpClientImpl(12) next expired: 0
08:07:56.362 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [83s 558ms] HttpClientImpl(12) Next deadline is 3000
08:07:56.363 DEBUG [HttpClientImpl.sendAsync] - [pool-2-thread-1] [83s 559ms] HttpClientImpl(12) ClientImpl (async) send http://localhost:25209/session POST
08:07:56.365 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [83s 560ms] HttpClientImpl(12) next timeout: 300000
08:07:56.365 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [83s 560ms] HttpClientImpl(12) next expired: 0
08:07:56.365 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [83s 561ms] HttpClientImpl(12) Next deadline is 3000
08:07:56.367 DEBUG [Exchange.establishExchange] - [pool-14-thread-1] [83s 562ms] Exchange establishing exchange for http://localhost:25209/session POST,
proxy=null
08:07:56.368 DEBUG [Http2ClientImpl.getConnectionFor] - [pool-14-thread-1] [83s 563ms] Http2ClientImpl not found in connection pool
08:07:56.369 DEBUG [ExchangeImpl.get] - [pool-14-thread-1] [83s 564ms] ExchangeImpl get: Trying to get HTTP/2 connection
08:07:56.370 DEBUG [ExchangeImpl.createExchangeImpl] - [pool-14-thread-1] [83s 565ms] ExchangeImpl handling HTTP/2 connection creation result
08:07:56.370 DEBUG [ExchangeImpl.createExchangeImpl] - [pool-14-thread-1] [83s 566ms] ExchangeImpl new Http1Exchange, try to upgrade
08:07:56.372 DEBUG [PlainHttpConnection.<init>] - [pool-14-thread-1] [83s 567ms] PlainHttpConnection(?) Initial receive buffer size is: 65536
08:07:56.373 DEBUG [Exchange.checkFor407] - [pool-14-thread-1] [83s 568ms] Exchange checkFor407: all clear
08:07:56.373 DEBUG [Http1Exchange.sendHeadersAsync] - [pool-14-thread-1] [83s 569ms] Http1Exchange Sending headers only
08:07:56.374 DEBUG [Http1AsyncReceiver.subscribe] - [pool-14-thread-1] [83s 570ms] Http1AsyncReceiver(SocketTube(12)) Subscribed pending jdk.internal.net.http.Http1Response$HeadersReader@59438e78 queue.isEmpty: true
08:07:56.375 DEBUG [Http1AsyncReceiver.handlePendingDelegate] - [pool-14-thread-1] [83s 571ms] Http1AsyncReceiver(SocketTube(12)) delegate is now jdk.internal.net.http.Http1Response$HeadersReader@59438e78, demand=1, canRequestMore=true, queue.isEmpty=true
08:07:56.376 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-14-thread-1] [83s 571ms] Http1AsyncReceiver(SocketTube(12)) downstream subscription demand is 1
08:07:56.377 DEBUG [Http1AsyncReceiver.checkRequestMore] - [pool-14-thread-1] [83s 572ms] Http1AsyncReceiver(SocketTube(12)) checkRequestMore: canRequestMore=true, hasDemand=true
08:07:56.377 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-14-thread-1] [83s 573ms] Http1AsyncReceiver(SocketTube(12)) downstream subscription demand is 1
08:07:56.378 DEBUG [Http1AsyncReceiver.checkRequestMore] - [pool-14-thread-1] [83s 574ms] Http1AsyncReceiver(SocketTube(12)) checkRequestMore: canRequestMore=true, hasDemand=true
08:07:56.379 DEBUG [Http1Exchange.sendHeadersAsync] - [pool-14-thread-1] [83s 574ms] Http1Exchange response created in advance
08:07:56.379 DEBUG [Http1Exchange.sendHeadersAsync] - [pool-14-thread-1] [83s 575ms] Http1Exchange initiating connect async
08:07:56.380 DEBUG [PlainHttpConnection.connectAsync] - [pool-14-thread-1] [83s 576ms] PlainHttpConnection(SocketTube(12)) registering connect timer: ConnectTimerEvent, TimeoutEvent[id=46, duration=PT10S, deadline=2023-09-25T08:08:06.380593Z]
08:07:56.381 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [83s 577ms] HttpClientImpl(12) next timeout: 9999
08:07:56.381 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [83s 577ms] HttpClientImpl(12) next expired: 0
08:07:56.381 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [83s 577ms] HttpClientImpl(12) Next deadline is 3000
08:07:56.382 DEBUG [PlainHttpConnection.connectAsync] - [pool-14-thread-1] [83s 578ms] PlainHttpConnection(SocketTube(12)) registering connect event
08:07:56.383 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-12-SelectorManager] [83s 579ms] SelectorAttachment Registering jdk.internal.net.http.PlainHttpConnection$ConnectEvent@12250d99 for 8 (true)
08:07:56.383 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [83s 579ms] HttpClientImpl(12) next timeout: 9997
08:07:56.383 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [83s 579ms] HttpClientImpl(12) next expired: 0
08:07:56.383 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [83s 579ms] HttpClientImpl(12) Next deadline is 3000
08:07:56.383 DEBUG [PlainHttpConnection$ConnectEvent.handle] - [HttpClient-12-SelectorManager] [83s 579ms] PlainHttpConnection(SocketTube(12)) ConnectEvent: finishing connect
08:07:56.383 DEBUG [PlainHttpConnection$ConnectEvent.handle] - [HttpClient-12-SelectorManager] [83s 579ms] PlainHttpConnection(SocketTube(12)) ConnectEvent: connect finished: true Local addr: /127.0.0.1:39922
08:07:56.385 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [83s 581ms] HttpClientImpl(12) next timeout: 9995
08:07:56.385 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [83s 581ms] HttpClientImpl(12) next expired: 0
08:07:56.385 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [83s 581ms] HttpClientImpl(12) Next deadline is 3000
08:07:56.387 DEBUG [PlainHttpConnection.finishConnect] - [pool-14-thread-2] [83s 582ms] PlainHttpConnection(SocketTube(12)) finishConnect, setting connected=true
08:07:56.387 DEBUG [Http1Exchange.connectFlows] - [pool-14-thread-2] [83s 583ms] Http1Exchange SocketTube(12) connecting flows
08:07:56.388 DEBUG [SocketTube.connectFlows] - [pool-14-thread-2] [83s 584ms] SocketTube(12) connecting flows
08:07:56.389 DEBUG [SocketTube$InternalReadPublisher.subscribe] - [pool-14-thread-2] [83s 584ms] SocketTube(12) read publisher got subscriber
08:07:56.390 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.signalSubscribe] - [pool-14-thread-2] [83s 585ms] SocketTube(12) registering subscribe event
08:07:56.390 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handleSubscribeEvent] - [HttpClient-12-SelectorManager] [83s 586ms] SocketTube(12) subscribe event raised
08:07:56.390 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-12-SelectorManager] [83s 586ms] SocketTube(12) handling pending subscription for jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber@5ddfeb96
08:07:56.390 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-12-SelectorManager] [83s 586ms] SocketTube(12) read demand reset to 0
08:07:56.390 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-12-SelectorManager] [83s 586ms] SocketTube(12) calling onSubscribe
08:07:56.390 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.onSubscribe] - [HttpClient-12-SelectorManager] [83s 586ms] Http1AsyncReceiver(SocketTube(12)) Received onSubscribed from upstream
08:07:56.390 DEBUG [SocketTube$InternalReadPublisher$ReadSubscription.signalOnSubscribe] - [HttpClient-12-SelectorManager] [83s 586ms] SocketTube(12) onSubscribe called
08:07:56.391 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-12-SelectorManager] [83s 586ms] SocketTube(12) pending subscriber subscribed
08:07:56.391 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [83s 586ms] HttpClientImpl(12) next timeout: 299974
08:07:56.391 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [83s 586ms] HttpClientImpl(12) next expired: 0
08:07:56.391 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [83s 586ms] HttpClientImpl(12) Next deadline is 3000
08:07:56.394 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-14-thread-1] [83s 589ms] Http1AsyncReceiver(SocketTube(12)) downstream subscription demand is 1
08:07:56.394 DEBUG [Http1AsyncReceiver.checkRequestMore] - [pool-14-thread-1] [83s 589ms] Http1AsyncReceiver(SocketTube(12)) checkRequestMore: canRequestMore=true, hasDemand=true
08:07:56.394 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.requestMore] - [pool-14-thread-1] [83s 589ms] Http1AsyncReceiver(SocketTube(12)) Http1TubeSubscriber: requesting one more from upstream
08:07:56.394 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.request] - [pool-14-thread-1] [83s 589ms] SocketTube(12) got some demand for reading
08:07:56.394 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [pool-14-thread-1] [83s 589ms] SocketTube(12) resuming read event
08:07:56.394 DEBUG [SocketTube.debugState] - [pool-14-thread-1] [83s 589ms] SocketTube(12) leaving request(1): Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=0]
08:07:56.394 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-12-SelectorManager] [83s 589ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@672c6c71 for 1 (true)
08:07:56.394 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [83s 589ms] HttpClientImpl(12) next timeout: 299971
08:07:56.394 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [83s 589ms] HttpClientImpl(12) next expired: 0
08:07:56.394 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [83s 590ms] HttpClientImpl(12) Next deadline is 3000
08:07:56.397 DEBUG [SocketTube.debugState] - [pool-14-thread-2] [83s 593ms] SocketTube(12) leaving read.subscribe: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=0]
08:07:56.398 DEBUG [Http1Exchange$Http1Publisher.subscribe] - [pool-14-thread-2] [83s 593ms] Http1Publisher(SocketTube(12)) got subscriber: SocketTube(12)
08:07:56.398 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-14-thread-2] [83s 594ms] SocketTube(12) subscribed for writing
08:07:56.399 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-14-thread-2] [83s 594ms] SocketTube(12) write: registering startSubscription event
08:07:56.400 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-12-SelectorManager] [83s 595ms] SocketTube(12) write: starting subscription
08:07:56.400 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-12-SelectorManager] [83s 595ms] SocketTube(12) write: offloading requestMore
08:07:56.400 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [83s 595ms] HttpClientImpl(12) next timeout: 299965
08:07:56.400 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [83s 595ms] HttpClientImpl(12) next expired: 0
08:07:56.400 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [83s 595ms] HttpClientImpl(12) Next deadline is 3000
08:07:56.401 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-14-thread-1] [83s 597ms] SocketTube(12) write: requesting more...
08:07:56.401 DEBUG [Http1Exchange$Http1Publisher$Http1WriteSubscription.request] - [pool-14-thread-1] [83s 597ms] Http1Publisher(SocketTube(12)) subscription request(1), demand=1
08:07:56.401 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-14-thread-1] [83s 597ms] Http1Publisher(SocketTube(12)) WriteTask
08:07:56.401 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-14-thread-1] [83s 597ms] Http1Publisher(SocketTube(12)) hasOutgoing = false
08:07:56.401 DEBUG [SocketTube.debugState] - [pool-14-thread-1] [83s 597ms] SocketTube(12) leaving requestMore: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
08:07:56.403 DEBUG [Http1Exchange.lambda$sendHeadersAsync$4] - [pool-14-thread-2] [83s 598ms] Http1Exchange requestAction.headers
08:07:56.404 DEBUG [Http1Exchange.lambda$sendHeadersAsync$4] - [pool-14-thread-2] [83s 599ms] Http1Exchange setting outgoing with headers
08:07:56.405 DEBUG [Http1Exchange.appendToOutgoing] - [pool-14-thread-2] [83s 600ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=337 cap=337]], throwable=null]
08:07:56.405 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-14-thread-2] [83s 601ms] Http1Publisher(SocketTube(12)) WriteTask
08:07:56.406 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-14-thread-2] [83s 601ms] Http1Publisher(SocketTube(12)) hasOutgoing = true
08:07:56.407 DEBUG [Http1Exchange.getOutgoing] - [pool-14-thread-2] [83s 602ms] Http1Exchange initiating completion of headersSentCF
08:07:56.408 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-14-thread-2] [83s 603ms] Http1Publisher(SocketTube(12)) onNext with 337 bytes
08:07:56.408 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [pool-14-thread-2] [83s 604ms] SocketTube(12) trying to write: 337
08:07:56.409 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [pool-14-thread-2] [83s 605ms] SocketTube(12) wrote: 337
08:07:56.410 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-14-thread-2] [83s 605ms] SocketTube(12) write: requesting more...
08:07:56.411 DEBUG [Http1Exchange$Http1Publisher$Http1WriteSubscription.request] - [pool-14-thread-2] [83s 606ms] Http1Publisher(SocketTube(12)) subscription request(1), demand=1
08:07:56.411 DEBUG [SocketTube.debugState] - [pool-14-thread-2] [83s 607ms] SocketTube(12) leaving requestMore: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
08:07:56.412 DEBUG [SocketTube.debugState] - [pool-14-thread-2] [83s 608ms] SocketTube(12) leaving w.onNext Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
08:07:56.417 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-14-thread-2] [83s 612ms] Http1Publisher(SocketTube(12)) WriteTask
08:07:56.417 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-14-thread-2] [83s 613ms] Http1Publisher(SocketTube(12)) hasOutgoing = false
08:07:56.418 DEBUG [Exchange.checkFor407] - [pool-14-thread-2] [83s 614ms] Exchange checkFor407: all clear
08:07:56.419 DEBUG [Exchange.sendRequestBody] - [pool-14-thread-2] [83s 614ms] Exchange sendRequestBody
08:07:56.420 DEBUG [Http1Exchange.sendBodyAsync] - [pool-14-thread-2] [83s 615ms] Http1Exchange sendBodyAsync
08:07:56.422 DEBUG [Http1Exchange.sendBodyAsync] - [pool-14-thread-2] [83s 617ms] Http1Exchange bodySubscriber is class jdk.internal.net.http.Http1Request$FixedContentSubscriber
08:07:56.422 DEBUG [Http1Exchange.requestMoreBody] - [pool-14-thread-2] [83s 617ms] Http1Exchange requesting more request body from the subscriber
08:07:56.422 DEBUG [Http1Exchange$Http1BodySubscriber.request] - [pool-14-thread-2] [83s 617ms] jdk.internal.net.http.Http1Request@6d2c0968 Http1BodySubscriber requesting 1, from jdk.internal.net.http.PullPublisher$Subscription@63ebfb65
08:07:56.422 DEBUG [Http1Request$FixedContentSubscriber.onNext] - [pool-14-thread-2] [83s 617ms] jdk.internal.net.http.Http1Request@6d2c0968 onNext
08:07:56.422 DEBUG [Http1Exchange.appendToOutgoing] - [pool-14-thread-2] [83s 617ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=483 cap=16384]], throwable=null]
08:07:56.422 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-14-thread-2] [83s 617ms] Http1Publisher(SocketTube(12)) WriteTask
08:07:56.422 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-14-thread-2] [83s 617ms] Http1Publisher(SocketTube(12)) hasOutgoing = true
08:07:56.422 DEBUG [Http1Exchange.requestMoreBody] - [pool-14-thread-2] [83s 617ms] Http1Exchange requesting more request body from the subscriber
08:07:56.422 DEBUG [Http1Exchange$Http1BodySubscriber.request] - [pool-14-thread-2] [83s 618ms] jdk.internal.net.http.Http1Request@6d2c0968 Http1BodySubscriber requesting 1, from jdk.internal.net.http.PullPublisher$Subscription@63ebfb65
08:07:56.422 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-14-thread-2] [83s 618ms] Http1Publisher(SocketTube(12)) onNext with 483 bytes
08:07:56.422 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [pool-14-thread-2] [83s 618ms] SocketTube(12) trying to write: 483
08:07:56.427 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [pool-14-thread-2] [83s 623ms] SocketTube(12) wrote: 483
08:07:56.428 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-14-thread-2] [83s 623ms] SocketTube(12) write: requesting more...
08:07:56.435 DEBUG [Http1Exchange$Http1Publisher$Http1WriteSubscription.request] - [pool-14-thread-2] [83s 630ms] Http1Publisher(SocketTube(12)) subscription request(1), demand=1
08:07:56.436 DEBUG [SocketTube.debugState] - [pool-14-thread-2] [83s 632ms] SocketTube(12) leaving requestMore: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
08:07:56.437 DEBUG [SocketTube.debugState] - [pool-14-thread-2] [83s 632ms] SocketTube(12) leaving w.onNext Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
08:07:56.437 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-14-thread-2] [83s 633ms] Http1Publisher(SocketTube(12)) WriteTask
08:07:56.438 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-14-thread-2] [83s 634ms] Http1Publisher(SocketTube(12)) hasOutgoing = false
08:07:56.439 DEBUG [Http1Request$FixedContentSubscriber.onComplete] - [pool-14-thread-2] [83s 634ms] jdk.internal.net.http.Http1Request@6d2c0968 onComplete
08:07:56.440 DEBUG [Http1Exchange.appendToOutgoing] - [pool-14-thread-2] [83s 635ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=0 cap=0]], throwable=null]
08:07:56.440 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-14-thread-2] [83s 636ms] Http1Publisher(SocketTube(12)) WriteTask
08:07:56.441 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-14-thread-2] [83s 637ms] Http1Publisher(SocketTube(12)) hasOutgoing = true
08:07:56.441 DEBUG [Http1Exchange.getOutgoing] - [pool-14-thread-2] [83s 637ms] Http1Exchange initiating completion of bodySentCF
08:07:56.441 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-14-thread-2] [83s 637ms] Http1Publisher(SocketTube(12)) completed, stopping jdk.internal.net.http.common.SequentialScheduler@69139015
08:07:56.441 DEBUG [Utils.lambda$wrapForDebug$8] - [pool-14-thread-2] [83s 637ms] Http1Exchange sendBodyAsync completed successfully
08:07:56.441 DEBUG [Http1Exchange.getResponseAsync] - [pool-14-thread-2] [83s 637ms] Http1Exchange reading headers
08:07:56.441 DEBUG [Http1Response.readHeadersAsync] - [pool-14-thread-2] [83s 637ms] Http1Response(id=34, PlainHttpConnection(SocketTube(12))) Reading Headers: (remaining: 0) READING_HEADERS
08:07:56.441 DEBUG [Http1Response.readHeadersAsync] - [pool-14-thread-2] [83s 637ms] Http1Response(id=34, PlainHttpConnection(SocketTube(12))) First time around
08:07:56.442 DEBUG [Http1Response.readHeadersAsync] - [pool-14-thread-2] [83s 637ms] Http1Response(id=34, PlainHttpConnection(SocketTube(12))) headersReader is not yet completed
08:07:56.865 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-11-SelectorManager] [84s 61ms] HttpClientImpl(11) next timeout: 0
08:07:56.865 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-11-SelectorManager] [84s 61ms] HttpClientImpl(11) next expired: 0
08:07:56.865 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-11-SelectorManager] [84s 61ms] HttpClientImpl(11) Next deadline is 3000
08:07:57.246 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-12-SelectorManager] [84s 442ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@672c6c71 for 0 (false)
08:07:57.246 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-12-SelectorManager] [84s 442ms] SocketTube(12) read bytes: 957
08:07:57.246 DEBUG [Http1AsyncReceiver.asyncReceive] - [HttpClient-12-SelectorManager] [84s 442ms] Http1AsyncReceiver(SocketTube(12)) Putting 957 bytes into the queue
08:07:57.247 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [HttpClient-12-SelectorManager] [84s 442ms] SocketTube(12) resuming read event
08:07:57.247 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-12-SelectorManager] [84s 442ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@672c6c71 for 1 (false)
08:07:57.247 DEBUG [SocketTube.debugState] - [HttpClient-12-SelectorManager] [84s 442ms] SocketTube(12) leaving read() loop after onNext: Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
08:07:57.247 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 442ms] HttpClientImpl(12) next timeout: 299118
08:07:57.247 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 442ms] HttpClientImpl(12) next expired: 0
08:07:57.247 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 442ms] HttpClientImpl(12) Next deadline is 3000
08:07:57.247 DEBUG [Http1AsyncReceiver.flush] - [pool-14-thread-2] [84s 442ms] Http1AsyncReceiver(SocketTube(12)) Got 957 bytes for delegate jdk.internal.net.http.Http1Response$HeadersReader@59438e78
08:07:57.247 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-14-thread-2] [84s 442ms] Http1AsyncReceiver(SocketTube(12)) downstream subscription demand is 1
08:07:57.247 DEBUG [Http1AsyncReceiver.flush] - [pool-14-thread-2] [84s 442ms] Http1AsyncReceiver(SocketTube(12)) Forwarding 957 bytes to delegate jdk.internal.net.http.Http1Response$HeadersReader@59438e78
08:07:57.247 DEBUG [Http1Response$HeadersReader.handle] - [pool-14-thread-2] [84s 443ms] Http1Response(id=34, PlainHttpConnection(SocketTube(12))) Sending 957/957 bytes to header parser
08:07:57.247 DEBUG [Http1Response$HeadersReader.handle] - [pool-14-thread-2] [84s 443ms] Http1Response(id=34, PlainHttpConnection(SocketTube(12))) Parsing headers completed. bytes=109
08:07:57.253 DEBUG [Http1AsyncReceiver.unsubscribe] - [pool-14-thread-2] [84s 448ms] Http1AsyncReceiver(SocketTube(12)) Unsubscribed jdk.internal.net.http.Http1Response$HeadersReader@59438e78
08:07:57.253 DEBUG [Http1Response.lambda$readHeadersAsync$0] - [pool-14-thread-2] [84s 448ms] Http1Response(id=34, PlainHttpConnection(SocketTube(12))) Reading Headers: creating Response object; state is now READING_BODY
08:07:57.253 DEBUG [Utils.lambda$wrapForDebug$8] - [pool-14-thread-2] [84s 448ms] Http1Exchange getResponseAsync completed successfully
08:07:57.254 DEBUG [Http1Response.readBody] - [pool-14-thread-2] [84s 450ms] Http1Response(id=34, PlainHttpConnection(SocketTube(12))) readBody: return2Cache: true
08:07:57.254 DEBUG [Http1Response$ClientRefCountTracker.acquire] - [pool-14-thread-2] [84s 450ms] Http1Response(id=34, PlainHttpConnection(SocketTube(12))) Operation started: incrementing ref count for jdk.internal.net.http.HttpClientImpl@57847af8(12)
08:07:57.254 DEBUG [Http1AsyncReceiver.subscribe] - [pool-14-thread-2] [84s 450ms] Http1AsyncReceiver(SocketTube(12)) Subscribed pending jdk.internal.net.http.Http1Response$BodyReader@2c110353/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@101df567 queue.isEmpty: false
08:07:57.254 DEBUG [Http1AsyncReceiver.flush] - [pool-14-thread-2] [84s 450ms] Http1AsyncReceiver(SocketTube(12)) Delegate done: 848
08:07:57.254 DEBUG [ResponseContent$FixedLengthBodyParser.onSubscribe] - [pool-14-thread-2] [84s 450ms] PlainHttpConnection(SocketTube(12))/ResponseContent/FixedLengthBodyParser length=848, onSubscribe: jdk.internal.net.http.Http1Response$Http1BodySubscriber
08:07:57.254 DEBUG [Http1AsyncReceiver.handlePendingDelegate] - [pool-14-thread-2] [84s 450ms] Http1AsyncReceiver(SocketTube(12)) delegate is now jdk.internal.net.http.Http1Response$BodyReader@2c110353/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@101df567, demand=9223372036854775807, canRequestMore=false, queue.isEmpty=false
08:07:57.255 DEBUG [Http1AsyncReceiver.flush] - [pool-14-thread-2] [84s 450ms] Http1AsyncReceiver(SocketTube(12)) Got 848 bytes for delegate jdk.internal.net.http.Http1Response$BodyReader@2c110353/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@101df567
08:07:57.255 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-14-thread-2] [84s 450ms] Http1AsyncReceiver(SocketTube(12)) downstream subscription demand is 9223372036854775807
08:07:57.255 DEBUG [Http1AsyncReceiver.flush] - [pool-14-thread-2] [84s 450ms] Http1AsyncReceiver(SocketTube(12)) Forwarding 848 bytes to delegate jdk.internal.net.http.Http1Response$BodyReader@2c110353/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@101df567
08:07:57.255 DEBUG [Http1Response$BodyReader.handle] - [pool-14-thread-2] [84s 450ms] Http1Response(id=34, PlainHttpConnection(SocketTube(12))) Sending 848/957 bytes to body parser
08:07:57.255 DEBUG [ResponseContent$FixedLengthBodyParser.accept] - [pool-14-thread-2] [84s 450ms] PlainHttpConnection(SocketTube(12))/ResponseContent/FixedLengthBodyParser Parser got 848 bytes (848 remaining / 848)
08:07:57.255 DEBUG [ResponseContent$FixedLengthBodyParser.accept] - [pool-14-thread-2] [84s 450ms] PlainHttpConnection(SocketTube(12))/ResponseContent/FixedLengthBodyParser Parser got all expected bytes: completing
08:07:57.255 DEBUG [Http1AsyncReceiver.clear] - [pool-14-thread-2] [84s 450ms] Http1AsyncReceiver(SocketTube(12)) cleared
08:07:57.255 DEBUG [Http1Response.onFinished] - [pool-14-thread-2] [84s 450ms] Http1Response(id=34, PlainHttpConnection(SocketTube(12))) SocketTube(12): return to HTTP/1.1 pool
08:07:57.256 DEBUG [ConnectionPool.registerCleanupTrigger] - [pool-14-thread-2] [84s 452ms] ConnectionPool(12) registering CleanupTrigger(SocketTube(12))
08:07:57.256 DEBUG [SocketTube.connectFlows] - [pool-14-thread-2] [84s 452ms] SocketTube(12) connecting flows
08:07:57.256 DEBUG [SocketTube$InternalReadPublisher.subscribe] - [pool-14-thread-2] [84s 452ms] SocketTube(12) read publisher got subscriber
08:07:57.256 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.signalSubscribe] - [pool-14-thread-2] [84s 452ms] SocketTube(12) registering subscribe event
08:07:57.257 DEBUG [SocketTube.debugState] - [pool-14-thread-2] [84s 452ms] SocketTube(12) leaving read.subscribe: Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
08:07:57.257 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-14-thread-2] [84s 452ms] SocketTube(12) subscribed for writing
08:07:57.257 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.dropSubscription] - [pool-14-thread-2] [84s 452ms] SocketTube(12) write: resetting demand to 0
08:07:57.258 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-14-thread-2] [84s 453ms] SocketTube(12) write: registering startSubscription event
08:07:57.257 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handleSubscribeEvent] - [HttpClient-12-SelectorManager] [84s 453ms] SocketTube(12) subscribe event raised
08:07:57.260 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-12-SelectorManager] [84s 456ms] SocketTube(12) handling pending subscription for CleanupTrigger(SocketTube(12))
08:07:57.260 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.dropSubscription] - [HttpClient-12-SelectorManager] [84s 456ms] Http1AsyncReceiver(SocketTube(12)) Http1TubeSubscriber: dropSubscription
08:07:57.261 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-12-SelectorManager] [84s 456ms] SocketTube(12) read demand reset to 0
08:07:57.261 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-12-SelectorManager] [84s 456ms] SocketTube(12) calling onSubscribe
08:07:57.261 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.request] - [HttpClient-12-SelectorManager] [84s 456ms] SocketTube(12) got some demand for reading
08:07:57.265 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [HttpClient-12-SelectorManager] [84s 460ms] SocketTube(12) resuming read event
08:07:57.265 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-12-SelectorManager] [84s 460ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@672c6c71 for 1 (false)
08:07:57.265 DEBUG [SocketTube.debugState] - [HttpClient-12-SelectorManager] [84s 460ms] SocketTube(12) leaving request(1): Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=0]
08:07:57.265 DEBUG [SocketTube$InternalReadPublisher$ReadSubscription.signalOnSubscribe] - [HttpClient-12-SelectorManager] [84s 460ms] SocketTube(12) onSubscribe called
08:07:57.265 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-12-SelectorManager] [84s 460ms] SocketTube(12) pending subscriber subscribed
08:07:57.265 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 460ms] HttpClientImpl(12) next timeout: 0
08:07:57.265 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 460ms] HttpClientImpl(12) next expired: 1199735
08:07:57.265 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 460ms] HttpClientImpl(12) Next deadline is 3000
08:07:57.265 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-12-SelectorManager] [84s 461ms] SocketTube(12) write: starting subscription
08:07:57.265 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-12-SelectorManager] [84s 461ms] SocketTube(12) write: offloading requestMore
08:07:57.265 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-14-thread-1] [84s 461ms] SocketTube(12) write: requesting more...
08:07:57.265 DEBUG [SocketTube.debugState] - [pool-14-thread-1] [84s 461ms] SocketTube(12) leaving requestMore: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
08:07:57.267 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 462ms] HttpClientImpl(12) next timeout: 0
08:07:57.267 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 463ms] HttpClientImpl(12) next expired: 1199733
08:07:57.267 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 463ms] HttpClientImpl(12) Next deadline is 3000
08:07:57.268 DEBUG [Http1Response.lambda$readBody$2] - [pool-14-thread-2] [84s 463ms] Http1Response(id=34, PlainHttpConnection(SocketTube(12))) Finished reading body: READING_BODY
08:07:57.268 DEBUG [Http1Response$ClientRefCountTracker.tryRelease] - [pool-14-thread-2] [84s 463ms] Http1Response(id=34, PlainHttpConnection(SocketTube(12))) Operation finished: decrementing ref count for jdk.internal.net.http.HttpClientImpl@57847af8(12)
08:07:57.268 DEBUG [Http1AsyncReceiver.flush] - [pool-14-thread-2] [84s 463ms] Http1AsyncReceiver(SocketTube(12)) Delegate done: 0
08:07:57.268 DEBUG [Http1AsyncReceiver.flush] - [pool-14-thread-2] [84s 463ms] Http1AsyncReceiver(SocketTube(12)) Got 0 bytes for delegate null
08:07:57.270 DEBUG [JdkHttpClient.execute0] - Ending request (POST) /session in 910ms
08:07:57.270 DEBUG [SeleniumSpanExporter$1.lambda$export$4] - SpanData{spanContext=ImmutableSpanContext{traceId=a3c54304740d77c7758dd90c0271af71, spanId=10ca437f09c00c21, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=a3c54304740d77c7758dd90c0271af71, spanId=40e648bf7f30a0f3, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, 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=1695629276358117647, endEpochNanos=1695629277269530790, attributes=AttributesMap{data={http.method=POST, span.kind=client, http.target=/session, http.status_code=200}, capacity=128, totalAddedValues=4}, totalAttributeCount=4, events=[], totalRecordedEvents=0, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=OK, description=Kind: OK Description:}, hasEnded=true}
08:07:57.271 DEBUG [ProtocolHandshake.createSession] - Detected upstream dialect: W3C
08:07:57.274 DEBUG [CdpEndpointFinder.getReportedUri] - URI found: http://localhost:39529
08:07:57.275 DEBUG [SeleniumSpanExporter$1.lambda$export$4] - SpanData{spanContext=ImmutableSpanContext{traceId=a3c54304740d77c7758dd90c0271af71, spanId=40e648bf7f30a0f3, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=a3c54304740d77c7758dd90c0271af71, spanId=f99211d6db57c4c5, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, 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=driver_service_factory.apply, kind=INTERNAL, startEpochNanos=1695629276170600559, endEpochNanos=1695629277274518055, attributes=AttributesMap{data={session.capabilities={"browserName": "chrome","goog:chromeOptions": {"extensions": [],"args": []},"networkname:applicationName": "RSC","nodename:applicationName": "intns07","pageLoadStrategy": "normal","platformName": "linux","se:noVncPort": 7900,"se:vncEnabled": true}
}, capacity=128, totalAddedValues=1}, totalAttributeCount=1, events=[ImmutableEventData{name=Driver service created session, attributes={downstream.dialect="W3C", driver.response="(Response: SessionID: b431cf96bf9e537172877fa54f061215, State: success, Value: {acceptInsecureCerts=false, browserName=chrome, browserVersion=117.0.5938.88, chrome={chromedriverVersion=117.0.5938.88 (be6afae4721209be42944bbcd325665f9f44563b-refs/branch-heads/5938_62@{#9}), userDataDir=/tmp/.org.chromium.Chromium.G82NXb}, fedcm:accounts=true, goog:chromeOptions={debuggerAddress=localhost:39529}, networkConnectionEnabled=false, pageLoadStrategy=normal, platformName=linux, proxy=Proxy(), setWindowRect=true, strictFileInteractability=false, timeouts={implicit=0, pageLoad=300000, script=30000}, unhandledPromptBehavior=dismiss and notify, webauthn:extension:credBlob=true, webauthn:extension:largeBlob=true, webauthn:extension:minPinLength=true, webauthn:extension:prf=true, webauthn:virtualAuthenticators=true})", driver.url="http://localhost:25209", logger="org.openqa.selenium.grid.node.config.DriverServiceSessionFactory", session.capabilities="{"browserName": "chrome","goog:chromeOptions": {"extensions": [],"args": []},"networkname:applicationName": "RSC","nodename:applicationName": "intns07","pageLoadStrategy": "normal","platformName": "linux","se:noVncPort": 7900,"se:vncEnabled": true}
", upstream.dialect="W3C"}, epochNanos=1695629277274444585, totalAttributeCount=6}], totalRecordedEvents=1, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=UNSET, description=}, hasEnded=true}
08:07:57.280 DEBUG [SeleniumSpanExporter$1.lambda$export$3] - {"traceId": "a3c54304740d77c7758dd90c0271af71","eventTime": 1695629277274444585,"eventName": "Driver service created session","attributes": {"downstream.dialect": "W3C","driver.response": "(Response: SessionID: b431cf96bf9e537172877fa54f061215, State: success, Value: {acceptInsecureCerts=false, browserName=chrome, browserVersion=117.0.5938.88, chrome={chromedriverVersion=117.0.5938.88 (be6afae4721209be42944bbcd325665f9f44563b-refs\u002fbranch-heads\u002f5938_62@{#9}), userDataDir=\u002ftmp\u002f.org.chromium.Chromium.G82NXb}, fedcm:accounts=true, goog:chromeOptions={debuggerAddress=localhost:39529}, networkConnectionEnabled=false, pageLoadStrategy=normal, platformName=linux, proxy=Proxy(), setWindowRect=true, strictFileInteractability=false, timeouts={implicit=0, pageLoad=300000, script=30000}, unhandledPromptBehavior=dismiss and notify, webauthn:extension:credBlob=true, webauthn:extension:largeBlob=true, webauthn:extension:minPinLength=true, webauthn:extension:prf=true, webauthn:virtualAuthenticators=true})","driver.url": "http:\u002f\u002flocalhost:25209","logger": "org.openqa.selenium.grid.node.config.DriverServiceSessionFactory","session.capabilities": "{\"browserName\": \"chrome\",\"goog:chromeOptions\": {\"extensions\": [],\"args\": []},\"networkname:applicationName\": \"RSC\",\"nodename:applicationName\": \"intns07\",\"pageLoadStrategy\": \"normal\",\"platformName\": \"linux\",\"se:noVncPort\": 7900,\"se:vncEnabled\": true}\n","upstream.dialect": "W3C"}}
08:07:57.313 INFO [LocalNode.newSession] - Session created by the Node. Id: b431cf96bf9e537172877fa54f061215, Caps: Capabilities {acceptInsecureCerts: false, browserName: chrome, browserVersion: 117.0.5938.88, chrome: {chromedriverVersion: 117.0.5938.88 (be6afae47212..., userDataDir: /tmp/.org.chromium.Chromium...}, fedcm:accounts: true, goog:chromeOptions: {debuggerAddress: localhost:39529}, networkConnectionEnabled: false, networkname:applicationName: RSC, pageLoadStrategy: normal, platformName: linux, proxy: Proxy(), se:bidiEnabled: false, se:cdp: ws://172.17.0.2:4444/sessio..., se:cdpVersion: 117.0.5938.88, se:vnc: ws://172.17.0.2:4444/sessio..., se:vncEnabled: true, se:vncLocalAddress: ws://172.17.0.2:7900, setWindowRect: true, strictFileInteractability: false, timeouts: {implicit: 0, pageLoad: 300000, script: 30000}, unhandledPromptBehavior: dismiss and notify, webauthn:extension:credBlob: true, webauthn:extension:largeBlob: true, webauthn:extension:minPinLength: true, webauthn:extension:prf: true, webauthn:virtualAuthenticators: true}
08:07:57.318 DEBUG [SeleniumSpanExporter$1.lambda$export$4] - SpanData{spanContext=ImmutableSpanContext{traceId=a3c54304740d77c7758dd90c0271af71, spanId=f99211d6db57c4c5, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=a3c54304740d77c7758dd90c0271af71, spanId=a1f52cc598da6b6a, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, 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=node.new_session, kind=INTERNAL, startEpochNanos=1695629276170035697, endEpochNanos=1695629277318023307, attributes=AttributesMap{data={session.id=b431cf96bf9e537172877fa54f061215, session.capabilities={"acceptInsecureCerts": false,"browserName": "chrome","browserVersion": "117.0.5938.88","chrome": {"chromedriverVersion": "117.0.5938.88 (be6afae4721209be42944bbcd325665f9f44563b-refs\u002fbranch-heads\u002f5938_62@{#9})","userDataDir": "\u002ftmp\u002f.org.chromium.Chromium.G82NXb"},"fedcm:accounts": true,"goog:chromeOptions": {"debuggerAddress": "localhost:39529"},"networkConnectionEnabled": false,"pageLoadStrategy": "normal","platformName": "linux","proxy": {},"se:cdp": "http:\u002f\u002flocalhost:39529","se:cdpVersion": "117.0.5938.88","se:vncEnabled": true,"se:vncLocalAddress": "ws:\u002f\u002f172.17.0.2:7900","setWindowRect": true,"strictFileInteractability": false,"timeouts": {"implicit": 0,"pageLoad": 300000,"script": 30000},"unhandledPromptBehavior": "dismiss and notify","webauthn:extension:credBlob": true,"webauthn:extension:largeBlob": true,"webauthn:extension:minPinLength": true,"webauthn:extension:prf": true,"webauthn:virtualAuthenticators": true}
, downstream.dialect=W3C, session.uri=http://localhost:25209, upstream.dialect=W3C, current.session.count=0}, capacity=128, totalAddedValues=6}, totalAttributeCount=6, events=[], totalRecordedEvents=0, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=UNSET, description=}, hasEnded=true}
08:07:57.333 DEBUG [SeleniumSpanExporter$1.lambda$export$4] - SpanData{spanContext=ImmutableSpanContext{traceId=a3c54304740d77c7758dd90c0271af71, spanId=a1f52cc598da6b6a, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=a3c54304740d77c7758dd90c0271af71, spanId=dfd6cea1a0f1c158, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, 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=node.new_session, kind=INTERNAL, startEpochNanos=1695629276160000000, endEpochNanos=1695629277332988506, attributes=AttributesMap{data={http.method=POST, random.key=e793e131-1ccb-4046-ab88-194b717a528c, span.kind=server, http.target=/se/grid/node/session, http.status_code=200}, capacity=128, totalAddedValues=5}, totalAttributeCount=5, events=[ImmutableEventData{name=HTTP request execution complete, attributes={http.flavor=1, http.handler_class="org.openqa.selenium.grid.security.RequiresSecretFilter$$Lambda$503/0x0000000840262840", http.host="10.237.23.122:5454", http.method="POST", http.request_content_length="319", http.scheme="HTTP", http.status_code=200, http.target="/se/grid/node/session", http.user_agent="selenium/4.12.1 (java unix)"}, epochNanos=1695629277332968394, totalAttributeCount=9}], totalRecordedEvents=1, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=OK, description=Kind: OK Description:}, hasEnded=true}
08:07:57.337 DEBUG [SeleniumSpanExporter$1.lambda$export$3] - {"traceId": "a3c54304740d77c7758dd90c0271af71","eventTime": 1695629277332968394,"eventName": "HTTP request execution complete","attributes": {"http.flavor": 1,"http.handler_class": "org.openqa.selenium.grid.security.RequiresSecretFilter$$Lambda$503\u002f0x0000000840262840","http.host": "10.237.23.122:5454","http.method": "POST","http.request_content_length": "319","http.scheme": "HTTP","http.status_code": 200,"http.target": "\u002fse\u002fgrid\u002fnode\u002fsession","http.user_agent": "selenium\u002f4.12.1 (java unix)"}}
08:07:57.363 DEBUG [RequestConverter.channelRead0] - Incoming message: DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
POST /session/b431cf96bf9e537172877fa54f061215/url HTTP/1.1
Connection: Upgrade, HTTP2-Settings
Content-Length: 28
Host: 10.237.23.122:5454
HTTP2-Settings: AAEAAEAAAAIAAAABAAMAAABkAAQBAAAAAAUAAEAA
Upgrade: h2c
Accept: application/json
Accept-Encoding: identity
Cache-Control: no-cache
Content-Type: application/json;charset=UTF-8
traceparent: 00-a5709b1f444e950b817af24e0125aef7-fd64749ca7dcf26f-01
User-Agent: selenium/4.12.0 (python mac)
08:07:57.363 DEBUG [RequestConverter.channelRead0] - Start of http request: DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
POST /session/b431cf96bf9e537172877fa54f061215/url HTTP/1.1
Connection: Upgrade, HTTP2-Settings
Content-Length: 28
Host: 10.237.23.122:5454
HTTP2-Settings: AAEAAEAAAAIAAAABAAMAAABkAAQBAAAAAAUAAEAA
Upgrade: h2c
Accept: application/json
Accept-Encoding: identity
Cache-Control: no-cache
Content-Type: application/json;charset=UTF-8
traceparent: 00-a5709b1f444e950b817af24e0125aef7-fd64749ca7dcf26f-01
User-Agent: selenium/4.12.0 (python mac)
08:07:57.368 DEBUG [RequestConverter.channelRead0] - Incoming message: DefaultLastHttpContent(data: PooledSlicedByteBuf(ridx: 0, widx: 28, cap: 28/28, unwrapped: PooledUnsafeDirectByteBuf(ridx: 482, widx: 482, cap: 1024)), decoderResult: success)
08:07:57.369 DEBUG [RequestConverter.channelRead0] - End of http request: DefaultLastHttpContent(data: PooledSlicedByteBuf(ridx: 28, widx: 28, cap: 28/28, unwrapped: PooledUnsafeDirectByteBuf(ridx: 482, widx: 482, cap: 1024)), decoderResult: success)
08:07:57.369 DEBUG [SpanWrappedHttpHandler.execute] - Wrapping request. Before OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@fdefd3f, context={}, span id=0000000000000000, trace id=00000000000000000000000000000000} and after OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@fdefd3f, context={opentelemetry-trace-span-key=SdkSpan{traceId=a5709b1f444e950b817af24e0125aef7, spanId=59856969a527445a, parentSpanContext=ImmutableSpanContext{traceId=a5709b1f444e950b817af24e0125aef7, spanId=fd64749ca7dcf26f, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, name=node.forward_command, kind=INTERNAL, attributes=AttributesMap{data={random.key=88418593-5e9c-4dda-bf01-9e6709c268c0}, capacity=128, totalAddedValues=1}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1695629277369000000, endEpochNanos=0}}, span id=59856969a527445a, trace id=a5709b1f444e950b817af24e0125aef7}
08:07:57.370 DEBUG [HttpTracing.inject] - Injecting (POST) /session/b431cf96bf9e537172877fa54f061215/url into OpenTelemetrySpan{traceId=a5709b1f444e950b817af24e0125aef7,spanId=59856969a527445a} at org.openqa.selenium.remote.tracing.SpanWrappedHttpHandler:89
08:07:57.370 DEBUG [JdkHttpClient.execute0] - Executing request: (POST) /session/b431cf96bf9e537172877fa54f061215/url
08:07:57.370 DEBUG [HttpClientImpl.sendAsync] - [pool-2-thread-1] [84s 566ms] HttpClientImpl(12) ClientImpl (async) send http://localhost:25209/session/b431cf96bf9e537172877fa54f061215/url POST
08:07:57.370 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 566ms] HttpClientImpl(12) next timeout: 300000
08:07:57.371 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 566ms] HttpClientImpl(12) next expired: 1199630
08:07:57.371 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 566ms] HttpClientImpl(12) Next deadline is 3000
08:07:57.376 DEBUG [Exchange.establishExchange] - [pool-14-thread-2] [84s 571ms] Exchange establishing exchange for http://localhost:25209/session/b431cf96bf9e537172877fa54f061215/url POST,
proxy=null
08:07:57.376 DEBUG [Http2ClientImpl.getConnectionFor] - [pool-14-thread-2] [84s 571ms] Http2ClientImpl not found in connection pool
08:07:57.376 DEBUG [ExchangeImpl.get] - [pool-14-thread-2] [84s 571ms] ExchangeImpl get: Trying to get HTTP/2 connection
08:07:57.376 DEBUG [ExchangeImpl.createExchangeImpl] - [pool-14-thread-2] [84s 571ms] ExchangeImpl handling HTTP/2 connection creation result
08:07:57.376 DEBUG [ExchangeImpl.createExchangeImpl] - [pool-14-thread-2] [84s 571ms] ExchangeImpl new Http1Exchange, try to upgrade
08:07:57.376 DEBUG [HttpConnection.getConnection] - [pool-14-thread-2] [84s 572ms] HttpConnection(SocketTube(?)) SocketTube(12): plain connection retrieved from HTTP/1.1 pool
08:07:57.376 DEBUG [Exchange.checkFor407] - [pool-14-thread-2] [84s 572ms] Exchange checkFor407: all clear
08:07:57.376 DEBUG [Http1Exchange.sendHeadersAsync] - [pool-14-thread-2] [84s 572ms] Http1Exchange Sending headers only
08:07:57.376 DEBUG [Http1AsyncReceiver.subscribe] - [pool-14-thread-2] [84s 572ms] Http1AsyncReceiver(SocketTube(12)) Subscribed pending jdk.internal.net.http.Http1Response$HeadersReader@681161d6 queue.isEmpty: true
08:07:57.376 DEBUG [Http1AsyncReceiver.handlePendingDelegate] - [pool-14-thread-2] [84s 572ms] Http1AsyncReceiver(SocketTube(12)) delegate is now jdk.internal.net.http.Http1Response$HeadersReader@681161d6, demand=1, canRequestMore=true, queue.isEmpty=true
08:07:57.376 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-14-thread-2] [84s 572ms] Http1AsyncReceiver(SocketTube(12)) downstream subscription demand is 1
08:07:57.376 DEBUG [Http1AsyncReceiver.checkRequestMore] - [pool-14-thread-2] [84s 572ms] Http1AsyncReceiver(SocketTube(12)) checkRequestMore: canRequestMore=true, hasDemand=true
08:07:57.376 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-14-thread-2] [84s 572ms] Http1AsyncReceiver(SocketTube(12)) downstream subscription demand is 1
08:07:57.377 DEBUG [Http1AsyncReceiver.checkRequestMore] - [pool-14-thread-2] [84s 572ms] Http1AsyncReceiver(SocketTube(12)) checkRequestMore: canRequestMore=true, hasDemand=true
08:07:57.377 DEBUG [Http1Exchange.sendHeadersAsync] - [pool-14-thread-2] [84s 572ms] Http1Exchange response created in advance
08:07:57.377 DEBUG [Http1Exchange.connectFlows] - [pool-14-thread-2] [84s 572ms] Http1Exchange SocketTube(12) connecting flows
08:07:57.377 DEBUG [SocketTube.connectFlows] - [pool-14-thread-2] [84s 572ms] SocketTube(12) connecting flows
08:07:57.377 DEBUG [SocketTube$InternalReadPublisher.subscribe] - [pool-14-thread-2] [84s 572ms] SocketTube(12) read publisher got subscriber
08:07:57.377 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.signalSubscribe] - [pool-14-thread-2] [84s 572ms] SocketTube(12) registering subscribe event
08:07:57.377 DEBUG [SocketTube.debugState] - [pool-14-thread-2] [84s 572ms] SocketTube(12) leaving read.subscribe: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
08:07:57.377 DEBUG [Http1Exchange$Http1Publisher.subscribe] - [pool-14-thread-2] [84s 572ms] Http1Publisher(SocketTube(12)) got subscriber: SocketTube(12)
08:07:57.377 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-14-thread-2] [84s 572ms] SocketTube(12) subscribed for writing
08:07:57.377 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.dropSubscription] - [pool-14-thread-2] [84s 572ms] SocketTube(12) write: resetting demand to 0
08:07:57.377 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-14-thread-2] [84s 572ms] SocketTube(12) write: registering startSubscription event
08:07:57.377 DEBUG [Http1Exchange.lambda$sendHeadersAsync$4] - [pool-14-thread-2] [84s 572ms] Http1Exchange requestAction.headers
08:07:57.377 DEBUG [Http1Exchange.lambda$sendHeadersAsync$4] - [pool-14-thread-2] [84s 573ms] Http1Exchange setting outgoing with headers
08:07:57.377 DEBUG [Http1Exchange.appendToOutgoing] - [pool-14-thread-2] [84s 573ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=451 cap=451]], throwable=null]
08:07:57.377 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-14-thread-2] [84s 573ms] Http1Publisher(SocketTube(12)) WriteTask
08:07:57.377 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-14-thread-2] [84s 573ms] Http1Publisher(SocketTube(12)) hasOutgoing = true
08:07:57.377 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handleSubscribeEvent] - [HttpClient-12-SelectorManager] [84s 573ms] SocketTube(12) subscribe event raised
08:07:57.377 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-12-SelectorManager] [84s 573ms] SocketTube(12) handling pending subscription for jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber@1fd1cfee
08:07:57.377 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-12-SelectorManager] [84s 573ms] SocketTube(12) read demand reset to 0
08:07:57.377 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-12-SelectorManager] [84s 573ms] SocketTube(12) calling onSubscribe
08:07:57.377 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.onSubscribe] - [HttpClient-12-SelectorManager] [84s 573ms] Http1AsyncReceiver(SocketTube(12)) Received onSubscribed from upstream
08:07:57.377 DEBUG [SocketTube$InternalReadPublisher$ReadSubscription.signalOnSubscribe] - [HttpClient-12-SelectorManager] [84s 573ms] SocketTube(12) onSubscribe called
08:07:57.377 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-12-SelectorManager] [84s 573ms] SocketTube(12) pending subscriber subscribed
08:07:57.377 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-12-SelectorManager] [84s 573ms] SocketTube(12) write: starting subscription
08:07:57.377 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-12-SelectorManager] [84s 573ms] SocketTube(12) write: offloading requestMore
08:07:57.377 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 573ms] HttpClientImpl(12) next timeout: 299993
08:07:57.378 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 573ms] HttpClientImpl(12) next expired: 0
08:07:57.378 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 573ms] HttpClientImpl(12) Next deadline is 3000
08:07:57.378 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-14-thread-1] [84s 573ms] SocketTube(12) write: requesting more...
08:07:57.378 DEBUG [Http1Exchange$Http1Publisher$Http1WriteSubscription.request] - [pool-14-thread-1] [84s 573ms] Http1Publisher(SocketTube(12)) subscription request(1), demand=1
08:07:57.378 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-14-thread-1] [84s 573ms] Http1Publisher(SocketTube(12)) WriteTask
08:07:57.378 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-14-thread-1] [84s 573ms] Http1Publisher(SocketTube(12)) hasOutgoing = true
08:07:57.378 DEBUG [Http1Exchange.getOutgoing] - [pool-14-thread-1] [84s 573ms] Http1Exchange initiating completion of headersSentCF
08:07:57.378 DEBUG [Exchange.checkFor407] - [pool-14-thread-1] [84s 573ms] Exchange checkFor407: all clear
08:07:57.378 DEBUG [Exchange.sendRequestBody] - [pool-14-thread-1] [84s 573ms] Exchange sendRequestBody
08:07:57.378 DEBUG [Http1Exchange.sendBodyAsync] - [pool-14-thread-1] [84s 573ms] Http1Exchange sendBodyAsync
08:07:57.378 DEBUG [Http1Exchange.sendBodyAsync] - [pool-14-thread-1] [84s 573ms] Http1Exchange bodySubscriber is class jdk.internal.net.http.Http1Request$FixedContentSubscriber
08:07:57.378 DEBUG [Http1Exchange.requestMoreBody] - [pool-14-thread-1] [84s 573ms] Http1Exchange requesting more request body from the subscriber
08:07:57.378 DEBUG [Http1Exchange$Http1BodySubscriber.request] - [pool-14-thread-1] [84s 574ms] jdk.internal.net.http.Http1Request@187e8443 Http1BodySubscriber requesting 1, from jdk.internal.net.http.PullPublisher$Subscription@5d7c1188
08:07:57.378 DEBUG [Http1Request$FixedContentSubscriber.onNext] - [pool-14-thread-1] [84s 574ms] jdk.internal.net.http.Http1Request@187e8443 onNext
08:07:57.378 DEBUG [Http1Exchange.appendToOutgoing] - [pool-14-thread-1] [84s 574ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=28 cap=16384]], throwable=null]
08:07:57.378 DEBUG [Http1Request$FixedContentSubscriber.onComplete] - [pool-14-thread-1] [84s 574ms] jdk.internal.net.http.Http1Request@187e8443 onComplete
08:07:57.378 DEBUG [Http1Exchange.appendToOutgoing] - [pool-14-thread-1] [84s 574ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=0 cap=0]], throwable=null]
08:07:57.378 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-14-thread-1] [84s 574ms] Http1Publisher(SocketTube(12)) onNext with 451 bytes
08:07:57.378 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [pool-14-thread-1] [84s 574ms] SocketTube(12) trying to write: 451
08:07:57.379 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [pool-14-thread-1] [84s 574ms] SocketTube(12) wrote: 451
08:07:57.379 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-14-thread-1] [84s 574ms] SocketTube(12) write: requesting more...
08:07:57.379 DEBUG [Http1Exchange$Http1Publisher$Http1WriteSubscription.request] - [pool-14-thread-1] [84s 574ms] Http1Publisher(SocketTube(12)) subscription request(1), demand=1
08:07:57.379 DEBUG [SocketTube.debugState] - [pool-14-thread-1] [84s 574ms] SocketTube(12) leaving requestMore: Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
08:07:57.379 DEBUG [SocketTube.debugState] - [pool-14-thread-1] [84s 574ms] SocketTube(12) leaving w.onNext Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
08:07:57.379 DEBUG [Http1Exchange.requestMoreBody] - [pool-14-thread-1] [84s 574ms] Http1Exchange requesting more request body from the subscriber
08:07:57.379 DEBUG [Http1Exchange$Http1BodySubscriber.request] - [pool-14-thread-1] [84s 574ms] jdk.internal.net.http.Http1Request@187e8443 Http1BodySubscriber requesting 1, from jdk.internal.net.http.PullPublisher$Subscription@5d7c1188
08:07:57.379 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-14-thread-1] [84s 574ms] Http1Publisher(SocketTube(12)) onNext with 28 bytes
08:07:57.379 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [pool-14-thread-1] [84s 574ms] SocketTube(12) trying to write: 28
08:07:57.390 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [pool-14-thread-1] [84s 586ms] SocketTube(12) wrote: 28
08:07:57.390 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-14-thread-1] [84s 586ms] SocketTube(12) write: requesting more...
08:07:57.391 DEBUG [Http1Exchange$Http1Publisher$Http1WriteSubscription.request] - [pool-14-thread-1] [84s 586ms] Http1Publisher(SocketTube(12)) subscription request(1), demand=1
08:07:57.391 DEBUG [SocketTube.debugState] - [pool-14-thread-1] [84s 586ms] SocketTube(12) leaving requestMore: Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
08:07:57.391 DEBUG [SocketTube.debugState] - [pool-14-thread-1] [84s 586ms] SocketTube(12) leaving w.onNext Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
08:07:57.391 DEBUG [Http1Exchange.getOutgoing] - [pool-14-thread-1] [84s 586ms] Http1Exchange initiating completion of bodySentCF
08:07:57.391 DEBUG [Utils.lambda$wrapForDebug$8] - [pool-14-thread-1] [84s 586ms] Http1Exchange sendBodyAsync completed successfully
08:07:57.391 DEBUG [Http1Exchange.getResponseAsync] - [pool-14-thread-1] [84s 586ms] Http1Exchange reading headers
08:07:57.391 DEBUG [Http1Response.readHeadersAsync] - [pool-14-thread-1] [84s 586ms] Http1Response(id=35, PlainHttpConnection(SocketTube(12))) Reading Headers: (remaining: 0) READING_HEADERS
08:07:57.391 DEBUG [Http1Response.readHeadersAsync] - [pool-14-thread-1] [84s 586ms] Http1Response(id=35, PlainHttpConnection(SocketTube(12))) First time around
08:07:57.402 DEBUG [Http1Response.readHeadersAsync] - [pool-14-thread-1] [84s 597ms] Http1Response(id=35, PlainHttpConnection(SocketTube(12))) headersReader is not yet completed
08:07:57.402 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-14-thread-1] [84s 597ms] Http1Publisher(SocketTube(12)) completed, stopping jdk.internal.net.http.common.SequentialScheduler@6c597e0e
08:07:57.402 DEBUG [SocketTube.debugState] - [pool-14-thread-1] [84s 597ms] SocketTube(12) leaving requestMore: Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
08:07:57.400 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-14-thread-2] [84s 595ms] Http1AsyncReceiver(SocketTube(12)) downstream subscription demand is 1
08:07:57.404 DEBUG [Http1AsyncReceiver.checkRequestMore] - [pool-14-thread-2] [84s 599ms] Http1AsyncReceiver(SocketTube(12)) checkRequestMore: canRequestMore=true, hasDemand=true
08:07:57.404 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.requestMore] - [pool-14-thread-2] [84s 599ms] Http1AsyncReceiver(SocketTube(12)) Http1TubeSubscriber: requesting one more from upstream
08:07:57.404 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.request] - [pool-14-thread-2] [84s 599ms] SocketTube(12) got some demand for reading
08:07:57.404 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [pool-14-thread-2] [84s 600ms] SocketTube(12) resuming read event
08:07:57.406 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-12-SelectorManager] [84s 602ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@672c6c71 for 1 (false)
08:07:57.406 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 602ms] HttpClientImpl(12) next timeout: 299964
08:07:57.406 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 602ms] HttpClientImpl(12) next expired: 0
08:07:57.406 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 602ms] HttpClientImpl(12) Next deadline is 3000
08:07:57.408 DEBUG [SocketTube.debugState] - [pool-14-thread-2] [84s 604ms] SocketTube(12) leaving request(1): Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
08:07:57.465 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-12-SelectorManager] [84s 660ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@672c6c71 for 0 (false)
08:07:57.465 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-12-SelectorManager] [84s 660ms] SocketTube(12) read bytes: 122
08:07:57.465 DEBUG [Http1AsyncReceiver.asyncReceive] - [HttpClient-12-SelectorManager] [84s 660ms] Http1AsyncReceiver(SocketTube(12)) Putting 122 bytes into the queue
08:07:57.465 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [HttpClient-12-SelectorManager] [84s 660ms] SocketTube(12) resuming read event
08:07:57.465 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-12-SelectorManager] [84s 661ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@672c6c71 for 1 (false)
08:07:57.465 DEBUG [SocketTube.debugState] - [HttpClient-12-SelectorManager] [84s 661ms] SocketTube(12) leaving read() loop after onNext: Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
08:07:57.465 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 661ms] HttpClientImpl(12) next timeout: 299905
08:07:57.465 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 661ms] HttpClientImpl(12) next expired: 0
08:07:57.465 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 661ms] HttpClientImpl(12) Next deadline is 3000
08:07:57.468 DEBUG [Http1AsyncReceiver.flush] - [pool-14-thread-2] [84s 663ms] Http1AsyncReceiver(SocketTube(12)) Got 122 bytes for delegate jdk.internal.net.http.Http1Response$HeadersReader@681161d6
08:07:57.468 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-14-thread-2] [84s 663ms] Http1AsyncReceiver(SocketTube(12)) downstream subscription demand is 1
08:07:57.468 DEBUG [Http1AsyncReceiver.flush] - [pool-14-thread-2] [84s 663ms] Http1AsyncReceiver(SocketTube(12)) Forwarding 122 bytes to delegate jdk.internal.net.http.Http1Response$HeadersReader@681161d6
08:07:57.468 DEBUG [Http1Response$HeadersReader.handle] - [pool-14-thread-2] [84s 664ms] Http1Response(id=35, PlainHttpConnection(SocketTube(12))) Sending 122/122 bytes to header parser
08:07:57.468 DEBUG [Http1Response$HeadersReader.handle] - [pool-14-thread-2] [84s 664ms] Http1Response(id=35, PlainHttpConnection(SocketTube(12))) Parsing headers completed. bytes=108
08:07:57.468 DEBUG [Http1AsyncReceiver.unsubscribe] - [pool-14-thread-2] [84s 664ms] Http1AsyncReceiver(SocketTube(12)) Unsubscribed jdk.internal.net.http.Http1Response$HeadersReader@681161d6
08:07:57.468 DEBUG [Http1Response.lambda$readHeadersAsync$0] - [pool-14-thread-2] [84s 664ms] Http1Response(id=35, PlainHttpConnection(SocketTube(12))) Reading Headers: creating Response object; state is now READING_BODY
08:07:57.468 DEBUG [Utils.lambda$wrapForDebug$8] - [pool-14-thread-2] [84s 664ms] Http1Exchange getResponseAsync completed successfully
08:07:57.468 DEBUG [Http1Response.readBody] - [pool-14-thread-2] [84s 664ms] Http1Response(id=35, PlainHttpConnection(SocketTube(12))) readBody: return2Cache: true
08:07:57.468 DEBUG [Http1Response$ClientRefCountTracker.acquire] - [pool-14-thread-2] [84s 664ms] Http1Response(id=35, PlainHttpConnection(SocketTube(12))) Operation started: incrementing ref count for jdk.internal.net.http.HttpClientImpl@57847af8(12)
08:07:57.469 DEBUG [Http1AsyncReceiver.subscribe] - [pool-14-thread-2] [84s 664ms] Http1AsyncReceiver(SocketTube(12)) Subscribed pending jdk.internal.net.http.Http1Response$BodyReader@4c3efc1c/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@33f78e31 queue.isEmpty: false
08:07:57.469 DEBUG [Http1AsyncReceiver.flush] - [pool-14-thread-2] [84s 664ms] Http1AsyncReceiver(SocketTube(12)) Delegate done: 14
08:07:57.469 DEBUG [ResponseContent$FixedLengthBodyParser.onSubscribe] - [pool-14-thread-2] [84s 664ms] PlainHttpConnection(SocketTube(12))/ResponseContent/FixedLengthBodyParser length=14, onSubscribe: jdk.internal.net.http.Http1Response$Http1BodySubscriber
08:07:57.469 DEBUG [Http1AsyncReceiver.handlePendingDelegate] - [pool-14-thread-2] [84s 664ms] Http1AsyncReceiver(SocketTube(12)) delegate is now jdk.internal.net.http.Http1Response$BodyReader@4c3efc1c/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@33f78e31, demand=9223372036854775807, canRequestMore=false, queue.isEmpty=false
08:07:57.469 DEBUG [Http1AsyncReceiver.flush] - [pool-14-thread-2] [84s 664ms] Http1AsyncReceiver(SocketTube(12)) Got 14 bytes for delegate jdk.internal.net.http.Http1Response$BodyReader@4c3efc1c/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@33f78e31
08:07:57.469 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-14-thread-2] [84s 664ms] Http1AsyncReceiver(SocketTube(12)) downstream subscription demand is 9223372036854775807
08:07:57.469 DEBUG [Http1AsyncReceiver.flush] - [pool-14-thread-2] [84s 664ms] Http1AsyncReceiver(SocketTube(12)) Forwarding 14 bytes to delegate jdk.internal.net.http.Http1Response$BodyReader@4c3efc1c/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@33f78e31
08:07:57.469 DEBUG [Http1Response$BodyReader.handle] - [pool-14-thread-2] [84s 664ms] Http1Response(id=35, PlainHttpConnection(SocketTube(12))) Sending 14/122 bytes to body parser
08:07:57.469 DEBUG [ResponseContent$FixedLengthBodyParser.accept] - [pool-14-thread-2] [84s 664ms] PlainHttpConnection(SocketTube(12))/ResponseContent/FixedLengthBodyParser Parser got 14 bytes (14 remaining / 14)
08:07:57.469 DEBUG [ResponseContent$FixedLengthBodyParser.accept] - [pool-14-thread-2] [84s 664ms] PlainHttpConnection(SocketTube(12))/ResponseContent/FixedLengthBodyParser Parser got all expected bytes: completing
08:07:57.469 DEBUG [Http1AsyncReceiver.clear] - [pool-14-thread-2] [84s 664ms] Http1AsyncReceiver(SocketTube(12)) cleared
08:07:57.469 DEBUG [Http1Response.onFinished] - [pool-14-thread-2] [84s 664ms] Http1Response(id=35, PlainHttpConnection(SocketTube(12))) SocketTube(12): return to HTTP/1.1 pool
08:07:57.469 DEBUG [ConnectionPool.registerCleanupTrigger] - [pool-14-thread-2] [84s 665ms] ConnectionPool(12) registering CleanupTrigger(SocketTube(12))
08:07:57.469 DEBUG [SocketTube.connectFlows] - [pool-14-thread-2] [84s 665ms] SocketTube(12) connecting flows
08:07:57.469 DEBUG [SocketTube$InternalReadPublisher.subscribe] - [pool-14-thread-2] [84s 665ms] SocketTube(12) read publisher got subscriber
08:07:57.469 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.signalSubscribe] - [pool-14-thread-2] [84s 665ms] SocketTube(12) registering subscribe event
08:07:57.469 DEBUG [SocketTube.debugState] - [pool-14-thread-2] [84s 665ms] SocketTube(12) leaving read.subscribe: Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
08:07:57.469 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-14-thread-2] [84s 665ms] SocketTube(12) subscribed for writing
08:07:57.469 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.dropSubscription] - [pool-14-thread-2] [84s 665ms] SocketTube(12) write: resetting demand to 0
08:07:57.469 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-14-thread-2] [84s 665ms] SocketTube(12) write: registering startSubscription event
08:07:57.477 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handleSubscribeEvent] - [HttpClient-12-SelectorManager] [84s 673ms] SocketTube(12) subscribe event raised
08:07:57.477 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-12-SelectorManager] [84s 673ms] SocketTube(12) handling pending subscription for CleanupTrigger(SocketTube(12))
08:07:57.477 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.dropSubscription] - [HttpClient-12-SelectorManager] [84s 673ms] Http1AsyncReceiver(SocketTube(12)) Http1TubeSubscriber: dropSubscription
08:07:57.477 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-12-SelectorManager] [84s 673ms] SocketTube(12) read demand reset to 0
08:07:57.477 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-12-SelectorManager] [84s 673ms] SocketTube(12) calling onSubscribe
08:07:57.477 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.request] - [HttpClient-12-SelectorManager] [84s 673ms] SocketTube(12) got some demand for reading
08:07:57.477 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [HttpClient-12-SelectorManager] [84s 673ms] SocketTube(12) resuming read event
08:07:57.477 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-12-SelectorManager] [84s 673ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@672c6c71 for 1 (false)
08:07:57.478 DEBUG [SocketTube.debugState] - [HttpClient-12-SelectorManager] [84s 673ms] SocketTube(12) leaving request(1): Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=0]
08:07:57.478 DEBUG [SocketTube$InternalReadPublisher$ReadSubscription.signalOnSubscribe] - [HttpClient-12-SelectorManager] [84s 673ms] SocketTube(12) onSubscribe called
08:07:57.478 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-12-SelectorManager] [84s 673ms] SocketTube(12) pending subscriber subscribed
08:07:57.478 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-12-SelectorManager] [84s 673ms] SocketTube(12) write: starting subscription
08:07:57.478 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-12-SelectorManager] [84s 673ms] SocketTube(12) write: offloading requestMore
08:07:57.478 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-14-thread-1] [84s 673ms] SocketTube(12) write: requesting more...
08:07:57.478 DEBUG [SocketTube.debugState] - [pool-14-thread-1] [84s 673ms] SocketTube(12) leaving requestMore: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
08:07:57.478 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 673ms] HttpClientImpl(12) next timeout: 0
08:07:57.478 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 673ms] HttpClientImpl(12) next expired: 1199522
08:07:57.478 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 673ms] HttpClientImpl(12) Next deadline is 3000
08:07:57.493 DEBUG [Http1Response.lambda$readBody$2] - [pool-14-thread-2] [84s 688ms] Http1Response(id=35, PlainHttpConnection(SocketTube(12))) Finished reading body: READING_BODY
08:07:57.494 DEBUG [Http1Response$ClientRefCountTracker.tryRelease] - [pool-14-thread-2] [84s 689ms] Http1Response(id=35, PlainHttpConnection(SocketTube(12))) Operation finished: decrementing ref count for jdk.internal.net.http.HttpClientImpl@57847af8(12)
08:07:57.494 DEBUG [Http1AsyncReceiver.flush] - [pool-14-thread-2] [84s 690ms] Http1AsyncReceiver(SocketTube(12)) Delegate done: 0
08:07:57.494 DEBUG [Http1AsyncReceiver.flush] - [pool-14-thread-2] [84s 690ms] Http1AsyncReceiver(SocketTube(12)) Got 0 bytes for delegate null
08:07:57.496 DEBUG [JdkHttpClient.execute0] - Ending request (POST) /session/b431cf96bf9e537172877fa54f061215/url in 126ms
08:07:57.496 DEBUG [SeleniumSpanExporter$1.lambda$export$4] - SpanData{spanContext=ImmutableSpanContext{traceId=a5709b1f444e950b817af24e0125aef7, spanId=bebcc79fdc42cc1a, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=a5709b1f444e950b817af24e0125aef7, spanId=59856969a527445a, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, 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=1695629277370000000, endEpochNanos=1695629277496088019, attributes=AttributesMap{data={http.method=POST, span.kind=client, http.target=/session/b431cf96bf9e537172877fa54f061215/url, http.status_code=200}, capacity=128, totalAddedValues=4}, totalAttributeCount=4, events=[], totalRecordedEvents=0, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=OK, description=Kind: OK Description:}, hasEnded=true}
08:07:57.496 DEBUG [SeleniumSpanExporter$1.lambda$export$4] - SpanData{spanContext=ImmutableSpanContext{traceId=a5709b1f444e950b817af24e0125aef7, spanId=ab64505aee516393, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=a5709b1f444e950b817af24e0125aef7, spanId=59856969a527445a, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, 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=reverse_proxy, kind=INTERNAL, startEpochNanos=1695629277370000000, endEpochNanos=1695629277496461094, attributes=AttributesMap{data={http.method=POST, http.target=/session/b431cf96bf9e537172877fa54f061215/url, http.status_code=200}, capacity=128, totalAddedValues=3}, totalAttributeCount=3, events=[], totalRecordedEvents=0, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=OK, description=Kind: OK Description:}, hasEnded=true}
08:07:57.496 DEBUG [SeleniumSpanExporter$1.lambda$export$4] - SpanData{spanContext=ImmutableSpanContext{traceId=a5709b1f444e950b817af24e0125aef7, spanId=59856969a527445a, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=a5709b1f444e950b817af24e0125aef7, spanId=fd64749ca7dcf26f, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, 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=node.forward_command, kind=INTERNAL, startEpochNanos=1695629277369000000, endEpochNanos=1695629277496119103, attributes=AttributesMap{data={http.method=POST, random.key=88418593-5e9c-4dda-bf01-9e6709c268c0, span.kind=server, http.target=/session/b431cf96bf9e537172877fa54f061215/url, http.status_code=200}, capacity=128, totalAddedValues=5}, totalAttributeCount=5, events=[ImmutableEventData{name=HTTP request execution complete, attributes={http.flavor=1, http.handler_class="org.openqa.selenium.remote.http.Route$PredicatedRoute", http.host="10.237.23.122:5454", http.method="POST", http.request_content_length="28", http.scheme="HTTP", http.status_code=200, http.target="/session/b431cf96bf9e537172877fa54f061215/url", http.user_agent="selenium/4.12.0 (python mac)"}, epochNanos=1695629277496110464, totalAttributeCount=9}], totalRecordedEvents=1, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=OK, description=Kind: OK Description:}, hasEnded=true}
08:07:57.497 DEBUG [SeleniumSpanExporter$1.lambda$export$3] - {"traceId": "a5709b1f444e950b817af24e0125aef7","eventTime": 1695629277496110464,"eventName": "HTTP request execution complete","attributes": {"http.flavor": 1,"http.handler_class": "org.openqa.selenium.remote.http.Route$PredicatedRoute","http.host": "10.237.23.122:5454","http.method": "POST","http.request_content_length": "28","http.scheme": "HTTP","http.status_code": 200,"http.target": "\u002fsession\u002fb431cf96bf9e537172877fa54f061215\u002furl","http.user_agent": "selenium\u002f4.12.0 (python mac)"}}
08:07:57.520 DEBUG [RequestConverter.channelRead0] - Incoming message: DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
DELETE /session/b431cf96bf9e537172877fa54f061215 HTTP/1.1
Connection: Upgrade, HTTP2-Settings
Content-Length: 0
Host: 10.237.23.122:5454
HTTP2-Settings: AAEAAEAAAAIAAAABAAMAAABkAAQBAAAAAAUAAEAA
Upgrade: h2c
Accept: application/json
Accept-Encoding: identity
Cache-Control: no-cache
Content-Type: application/json;charset=UTF-8
traceparent: 00-1d8227c55489824ded05b15ff25d9bad-46ee7293f802de85-01
User-Agent: selenium/4.12.0 (python mac)
08:07:57.520 DEBUG [RequestConverter.channelRead0] - Start of http request: DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
DELETE /session/b431cf96bf9e537172877fa54f061215 HTTP/1.1
Connection: Upgrade, HTTP2-Settings
Content-Length: 0
Host: 10.237.23.122:5454
HTTP2-Settings: AAEAAEAAAAIAAAABAAMAAABkAAQBAAAAAAUAAEAA
Upgrade: h2c
Accept: application/json
Accept-Encoding: identity
Cache-Control: no-cache
Content-Type: application/json;charset=UTF-8
traceparent: 00-1d8227c55489824ded05b15ff25d9bad-46ee7293f802de85-01
User-Agent: selenium/4.12.0 (python mac)
08:07:57.520 DEBUG [RequestConverter.channelRead0] - Incoming message: EmptyLastHttpContent
08:07:57.520 DEBUG [RequestConverter.channelRead0] - End of http request: EmptyLastHttpContent
08:07:57.527 DEBUG [SpanWrappedHttpHandler.execute] - Wrapping request. Before OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@fdefd3f, context={}, span id=0000000000000000, trace id=00000000000000000000000000000000} and after OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@fdefd3f, context={opentelemetry-trace-span-key=SdkSpan{traceId=1d8227c55489824ded05b15ff25d9bad, spanId=9df3a1c7e8886a9f, parentSpanContext=ImmutableSpanContext{traceId=1d8227c55489824ded05b15ff25d9bad, spanId=46ee7293f802de85, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, name=node.forward_command, kind=INTERNAL, attributes=AttributesMap{data={random.key=99aad0c9-009e-471a-9fc1-006bfd9f6ad5}, capacity=128, totalAddedValues=1}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1695629277527000000, endEpochNanos=0}}, span id=9df3a1c7e8886a9f, trace id=1d8227c55489824ded05b15ff25d9bad}
08:07:57.528 DEBUG [HttpTracing.inject] - Injecting (DELETE) /session/b431cf96bf9e537172877fa54f061215 into OpenTelemetrySpan{traceId=1d8227c55489824ded05b15ff25d9bad,spanId=9df3a1c7e8886a9f} at org.openqa.selenium.remote.tracing.SpanWrappedHttpHandler:89
08:07:57.528 DEBUG [JdkHttpClient.execute0] - Executing request: (DELETE) /session/b431cf96bf9e537172877fa54f061215
08:07:57.528 DEBUG [HttpClientImpl.sendAsync] - [pool-2-thread-1] [84s 724ms] HttpClientImpl(12) ClientImpl (async) send http://localhost:25209/session/b431cf96bf9e537172877fa54f061215 DELETE
08:07:57.529 DEBUG [Exchange.establishExchange] - [pool-14-thread-2] [84s 724ms] Exchange establishing exchange for http://localhost:25209/session/b431cf96bf9e537172877fa54f061215 DELETE,
proxy=null
08:07:57.529 DEBUG [Http2ClientImpl.getConnectionFor] - [pool-14-thread-2] [84s 724ms] Http2ClientImpl not found in connection pool
08:07:57.529 DEBUG [ExchangeImpl.get] - [pool-14-thread-2] [84s 724ms] ExchangeImpl get: Trying to get HTTP/2 connection
08:07:57.529 DEBUG [ExchangeImpl.createExchangeImpl] - [pool-14-thread-2] [84s 724ms] ExchangeImpl handling HTTP/2 connection creation result
08:07:57.529 DEBUG [ExchangeImpl.createExchangeImpl] - [pool-14-thread-2] [84s 724ms] ExchangeImpl new Http1Exchange, try to upgrade
08:07:57.529 DEBUG [HttpConnection.getConnection] - [pool-14-thread-2] [84s 724ms] HttpConnection(SocketTube(?)) SocketTube(12): plain connection retrieved from HTTP/1.1 pool
08:07:57.529 DEBUG [Exchange.checkFor407] - [pool-14-thread-2] [84s 724ms] Exchange checkFor407: all clear
08:07:57.529 DEBUG [Http1Exchange.sendHeadersAsync] - [pool-14-thread-2] [84s 725ms] Http1Exchange Sending headers only
08:07:57.529 DEBUG [Http1AsyncReceiver.subscribe] - [pool-14-thread-2] [84s 725ms] Http1AsyncReceiver(SocketTube(12)) Subscribed pending jdk.internal.net.http.Http1Response$HeadersReader@731508f1 queue.isEmpty: true
08:07:57.529 DEBUG [Http1AsyncReceiver.handlePendingDelegate] - [pool-14-thread-2] [84s 725ms] Http1AsyncReceiver(SocketTube(12)) delegate is now jdk.internal.net.http.Http1Response$HeadersReader@731508f1, demand=1, canRequestMore=true, queue.isEmpty=true
08:07:57.529 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-14-thread-2] [84s 725ms] Http1AsyncReceiver(SocketTube(12)) downstream subscription demand is 1
08:07:57.529 DEBUG [Http1AsyncReceiver.checkRequestMore] - [pool-14-thread-2] [84s 725ms] Http1AsyncReceiver(SocketTube(12)) checkRequestMore: canRequestMore=true, hasDemand=true
08:07:57.529 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-14-thread-2] [84s 725ms] Http1AsyncReceiver(SocketTube(12)) downstream subscription demand is 1
08:07:57.529 DEBUG [Http1AsyncReceiver.checkRequestMore] - [pool-14-thread-2] [84s 725ms] Http1AsyncReceiver(SocketTube(12)) checkRequestMore: canRequestMore=true, hasDemand=true
08:07:57.529 DEBUG [Http1Exchange.sendHeadersAsync] - [pool-14-thread-2] [84s 725ms] Http1Exchange response created in advance
08:07:57.529 DEBUG [Http1Exchange.connectFlows] - [pool-14-thread-2] [84s 725ms] Http1Exchange SocketTube(12) connecting flows
08:07:57.529 DEBUG [SocketTube.connectFlows] - [pool-14-thread-2] [84s 725ms] SocketTube(12) connecting flows
08:07:57.529 DEBUG [SocketTube$InternalReadPublisher.subscribe] - [pool-14-thread-2] [84s 725ms] SocketTube(12) read publisher got subscriber
08:07:57.529 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.signalSubscribe] - [pool-14-thread-2] [84s 725ms] SocketTube(12) registering subscribe event
08:07:57.529 DEBUG [SocketTube.debugState] - [pool-14-thread-2] [84s 725ms] SocketTube(12) leaving read.subscribe: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
08:07:57.529 DEBUG [Http1Exchange$Http1Publisher.subscribe] - [pool-14-thread-2] [84s 725ms] Http1Publisher(SocketTube(12)) got subscriber: SocketTube(12)
08:07:57.529 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-14-thread-2] [84s 725ms] SocketTube(12) subscribed for writing
08:07:57.530 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.dropSubscription] - [pool-14-thread-2] [84s 725ms] SocketTube(12) write: resetting demand to 0
08:07:57.530 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-14-thread-2] [84s 725ms] SocketTube(12) write: registering startSubscription event
08:07:57.530 DEBUG [Http1Exchange.lambda$sendHeadersAsync$4] - [pool-14-thread-2] [84s 725ms] Http1Exchange requestAction.headers
08:07:57.530 DEBUG [Http1Exchange.lambda$sendHeadersAsync$4] - [pool-14-thread-2] [84s 725ms] Http1Exchange setting outgoing with headers
08:07:57.530 DEBUG [Http1Exchange.appendToOutgoing] - [pool-14-thread-2] [84s 725ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=448 cap=448]], throwable=null]
08:07:57.530 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-14-thread-2] [84s 725ms] Http1Publisher(SocketTube(12)) WriteTask
08:07:57.530 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-14-thread-2] [84s 725ms] Http1Publisher(SocketTube(12)) hasOutgoing = true
08:07:57.533 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handleSubscribeEvent] - [HttpClient-12-SelectorManager] [84s 729ms] SocketTube(12) subscribe event raised
08:07:57.533 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-12-SelectorManager] [84s 729ms] SocketTube(12) handling pending subscription for jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber@3df014d9
08:07:57.533 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-12-SelectorManager] [84s 729ms] SocketTube(12) read demand reset to 0
08:07:57.533 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-12-SelectorManager] [84s 729ms] SocketTube(12) calling onSubscribe
08:07:57.533 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.onSubscribe] - [HttpClient-12-SelectorManager] [84s 729ms] Http1AsyncReceiver(SocketTube(12)) Received onSubscribed from upstream
08:07:57.534 DEBUG [SocketTube$InternalReadPublisher$ReadSubscription.signalOnSubscribe] - [HttpClient-12-SelectorManager] [84s 729ms] SocketTube(12) onSubscribe called
08:07:57.534 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-12-SelectorManager] [84s 729ms] SocketTube(12) pending subscriber subscribed
08:07:57.534 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-12-SelectorManager] [84s 729ms] SocketTube(12) write: starting subscription
08:07:57.534 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-12-SelectorManager] [84s 729ms] SocketTube(12) write: offloading requestMore
08:07:57.534 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 729ms] HttpClientImpl(12) next timeout: 299995
08:07:57.534 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 729ms] HttpClientImpl(12) next expired: 0
08:07:57.534 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 729ms] HttpClientImpl(12) Next deadline is 3000
08:07:57.534 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-14-thread-1] [84s 729ms] SocketTube(12) write: requesting more...
08:07:57.534 DEBUG [Http1Exchange$Http1Publisher$Http1WriteSubscription.request] - [pool-14-thread-1] [84s 729ms] Http1Publisher(SocketTube(12)) subscription request(1), demand=1
08:07:57.534 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-14-thread-1] [84s 729ms] Http1Publisher(SocketTube(12)) WriteTask
08:07:57.534 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-14-thread-1] [84s 729ms] Http1Publisher(SocketTube(12)) hasOutgoing = true
08:07:57.534 DEBUG [Http1Exchange.getOutgoing] - [pool-14-thread-1] [84s 730ms] Http1Exchange initiating completion of headersSentCF
08:07:57.534 DEBUG [Exchange.checkFor407] - [pool-14-thread-1] [84s 730ms] Exchange checkFor407: all clear
08:07:57.534 DEBUG [Exchange.sendRequestBody] - [pool-14-thread-1] [84s 730ms] Exchange sendRequestBody
08:07:57.534 DEBUG [Http1Exchange.sendBodyAsync] - [pool-14-thread-1] [84s 730ms] Http1Exchange sendBodyAsync
08:07:57.534 DEBUG [Http1Exchange.sendBodyAsync] - [pool-14-thread-1] [84s 730ms] Http1Exchange bodySubscriber is null
08:07:57.534 DEBUG [Http1Exchange.appendToOutgoing] - [pool-14-thread-1] [84s 730ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=0 cap=0]], throwable=null]
08:07:57.534 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-14-thread-1] [84s 730ms] Http1Publisher(SocketTube(12)) onNext with 448 bytes
08:07:57.534 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [pool-14-thread-1] [84s 730ms] SocketTube(12) trying to write: 448
08:07:57.534 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [pool-14-thread-1] [84s 730ms] SocketTube(12) wrote: 448
08:07:57.534 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-14-thread-1] [84s 730ms] SocketTube(12) write: requesting more...
08:07:57.534 DEBUG [Http1Exchange$Http1Publisher$Http1WriteSubscription.request] - [pool-14-thread-1] [84s 730ms] Http1Publisher(SocketTube(12)) subscription request(1), demand=1
08:07:57.535 DEBUG [SocketTube.debugState] - [pool-14-thread-1] [84s 730ms] SocketTube(12) leaving requestMore: Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
08:07:57.535 DEBUG [SocketTube.debugState] - [pool-14-thread-1] [84s 730ms] SocketTube(12) leaving w.onNext Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
08:07:57.535 DEBUG [Http1Exchange.getOutgoing] - [pool-14-thread-1] [84s 730ms] Http1Exchange initiating completion of bodySentCF
08:07:57.535 DEBUG [Utils.lambda$wrapForDebug$8] - [pool-14-thread-1] [84s 730ms] Http1Exchange sendBodyAsync completed successfully
08:07:57.535 DEBUG [Http1Exchange.getResponseAsync] - [pool-14-thread-1] [84s 730ms] Http1Exchange reading headers
08:07:57.535 DEBUG [Http1Response.readHeadersAsync] - [pool-14-thread-1] [84s 730ms] Http1Response(id=36, PlainHttpConnection(SocketTube(12))) Reading Headers: (remaining: 0) READING_HEADERS
08:07:57.535 DEBUG [Http1Response.readHeadersAsync] - [pool-14-thread-1] [84s 730ms] Http1Response(id=36, PlainHttpConnection(SocketTube(12))) First time around
08:07:57.535 DEBUG [Http1Response.readHeadersAsync] - [pool-14-thread-1] [84s 730ms] Http1Response(id=36, PlainHttpConnection(SocketTube(12))) headersReader is not yet completed
08:07:57.535 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-14-thread-1] [84s 730ms] Http1Publisher(SocketTube(12)) completed, stopping jdk.internal.net.http.common.SequentialScheduler@29ac1db3
08:07:57.535 DEBUG [SocketTube.debugState] - [pool-14-thread-1] [84s 730ms] SocketTube(12) leaving requestMore: Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
08:07:57.555 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-14-thread-2] [84s 750ms] Http1AsyncReceiver(SocketTube(12)) downstream subscription demand is 1
08:07:57.556 DEBUG [Http1AsyncReceiver.checkRequestMore] - [pool-14-thread-2] [84s 751ms] Http1AsyncReceiver(SocketTube(12)) checkRequestMore: canRequestMore=true, hasDemand=true
08:07:57.557 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.requestMore] - [pool-14-thread-2] [84s 752ms] Http1AsyncReceiver(SocketTube(12)) Http1TubeSubscriber: requesting one more from upstream
08:07:57.557 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.request] - [pool-14-thread-2] [84s 753ms] SocketTube(12) got some demand for reading
08:07:57.558 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [pool-14-thread-2] [84s 753ms] SocketTube(12) resuming read event
08:07:57.559 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-12-SelectorManager] [84s 754ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@672c6c71 for 1 (false)
08:07:57.563 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 758ms] HttpClientImpl(12) next timeout: 299966
08:07:57.563 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 758ms] HttpClientImpl(12) next expired: 0
08:07:57.563 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 758ms] HttpClientImpl(12) Next deadline is 3000
08:07:57.565 DEBUG [SocketTube.debugState] - [pool-14-thread-2] [84s 760ms] SocketTube(12) leaving request(1): Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
08:07:57.639 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-12-SelectorManager] [84s 835ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@672c6c71 for 0 (false)
08:07:57.640 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-12-SelectorManager] [84s 835ms] SocketTube(12) read bytes: 122
08:07:57.640 DEBUG [Http1AsyncReceiver.asyncReceive] - [HttpClient-12-SelectorManager] [84s 835ms] Http1AsyncReceiver(SocketTube(12)) Putting 122 bytes into the queue
08:07:57.640 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [HttpClient-12-SelectorManager] [84s 835ms] SocketTube(12) resuming read event
08:07:57.640 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-12-SelectorManager] [84s 835ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@672c6c71 for 1 (false)
08:07:57.640 DEBUG [SocketTube.debugState] - [HttpClient-12-SelectorManager] [84s 835ms] SocketTube(12) leaving read() loop after onNext: Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
08:07:57.640 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 835ms] HttpClientImpl(12) next timeout: 299889
08:07:57.640 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 835ms] HttpClientImpl(12) next expired: 0
08:07:57.640 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 835ms] HttpClientImpl(12) Next deadline is 3000
08:07:57.642 DEBUG [Http1AsyncReceiver.flush] - [pool-14-thread-2] [84s 838ms] Http1AsyncReceiver(SocketTube(12)) Got 122 bytes for delegate jdk.internal.net.http.Http1Response$HeadersReader@731508f1
08:07:57.643 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-14-thread-2] [84s 838ms] Http1AsyncReceiver(SocketTube(12)) downstream subscription demand is 1
08:07:57.643 DEBUG [Http1AsyncReceiver.flush] - [pool-14-thread-2] [84s 838ms] Http1AsyncReceiver(SocketTube(12)) Forwarding 122 bytes to delegate jdk.internal.net.http.Http1Response$HeadersReader@731508f1
08:07:57.643 DEBUG [Http1Response$HeadersReader.handle] - [pool-14-thread-2] [84s 838ms] Http1Response(id=36, PlainHttpConnection(SocketTube(12))) Sending 122/122 bytes to header parser
08:07:57.643 DEBUG [Http1Response$HeadersReader.handle] - [pool-14-thread-2] [84s 838ms] Http1Response(id=36, PlainHttpConnection(SocketTube(12))) Parsing headers completed. bytes=108
08:07:57.643 DEBUG [Http1AsyncReceiver.unsubscribe] - [pool-14-thread-2] [84s 838ms] Http1AsyncReceiver(SocketTube(12)) Unsubscribed jdk.internal.net.http.Http1Response$HeadersReader@731508f1
08:07:57.643 DEBUG [Http1Response.lambda$readHeadersAsync$0] - [pool-14-thread-2] [84s 838ms] Http1Response(id=36, PlainHttpConnection(SocketTube(12))) Reading Headers: creating Response object; state is now READING_BODY
08:07:57.645 DEBUG [Utils.lambda$wrapForDebug$8] - [pool-14-thread-2] [84s 841ms] Http1Exchange getResponseAsync completed successfully
08:07:57.645 DEBUG [Http1Response.readBody] - [pool-14-thread-2] [84s 841ms] Http1Response(id=36, PlainHttpConnection(SocketTube(12))) readBody: return2Cache: true
08:07:57.645 DEBUG [Http1Response$ClientRefCountTracker.acquire] - [pool-14-thread-2] [84s 841ms] Http1Response(id=36, PlainHttpConnection(SocketTube(12))) Operation started: incrementing ref count for jdk.internal.net.http.HttpClientImpl@57847af8(12)
08:07:57.645 DEBUG [Http1AsyncReceiver.subscribe] - [pool-14-thread-2] [84s 841ms] Http1AsyncReceiver(SocketTube(12)) Subscribed pending jdk.internal.net.http.Http1Response$BodyReader@4870c493/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@47795daa queue.isEmpty: false
08:07:57.646 DEBUG [Http1AsyncReceiver.flush] - [pool-14-thread-2] [84s 841ms] Http1AsyncReceiver(SocketTube(12)) Delegate done: 14
08:07:57.646 DEBUG [ResponseContent$FixedLengthBodyParser.onSubscribe] - [pool-14-thread-2] [84s 841ms] PlainHttpConnection(SocketTube(12))/ResponseContent/FixedLengthBodyParser length=14, onSubscribe: jdk.internal.net.http.Http1Response$Http1BodySubscriber
08:07:57.646 DEBUG [Http1AsyncReceiver.handlePendingDelegate] - [pool-14-thread-2] [84s 841ms] Http1AsyncReceiver(SocketTube(12)) delegate is now jdk.internal.net.http.Http1Response$BodyReader@4870c493/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@47795daa, demand=9223372036854775807, canRequestMore=false, queue.isEmpty=false
08:07:57.646 DEBUG [Http1AsyncReceiver.flush] - [pool-14-thread-2] [84s 841ms] Http1AsyncReceiver(SocketTube(12)) Got 14 bytes for delegate jdk.internal.net.http.Http1Response$BodyReader@4870c493/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@47795daa
08:07:57.646 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-14-thread-2] [84s 841ms] Http1AsyncReceiver(SocketTube(12)) downstream subscription demand is 9223372036854775807
08:07:57.646 DEBUG [Http1AsyncReceiver.flush] - [pool-14-thread-2] [84s 841ms] Http1AsyncReceiver(SocketTube(12)) Forwarding 14 bytes to delegate jdk.internal.net.http.Http1Response$BodyReader@4870c493/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@47795daa
08:07:57.646 DEBUG [Http1Response$BodyReader.handle] - [pool-14-thread-2] [84s 841ms] Http1Response(id=36, PlainHttpConnection(SocketTube(12))) Sending 14/122 bytes to body parser
08:07:57.646 DEBUG [ResponseContent$FixedLengthBodyParser.accept] - [pool-14-thread-2] [84s 841ms] PlainHttpConnection(SocketTube(12))/ResponseContent/FixedLengthBodyParser Parser got 14 bytes (14 remaining / 14)
08:07:57.646 DEBUG [ResponseContent$FixedLengthBodyParser.accept] - [pool-14-thread-2] [84s 841ms] PlainHttpConnection(SocketTube(12))/ResponseContent/FixedLengthBodyParser Parser got all expected bytes: completing
08:07:57.646 DEBUG [Http1AsyncReceiver.clear] - [pool-14-thread-2] [84s 841ms] Http1AsyncReceiver(SocketTube(12)) cleared
08:07:57.646 DEBUG [Http1Response.onFinished] - [pool-14-thread-2] [84s 841ms] Http1Response(id=36, PlainHttpConnection(SocketTube(12))) SocketTube(12): return to HTTP/1.1 pool
08:07:57.646 DEBUG [ConnectionPool.registerCleanupTrigger] - [pool-14-thread-2] [84s 841ms] ConnectionPool(12) registering CleanupTrigger(SocketTube(12))
08:07:57.650 DEBUG [SocketTube.connectFlows] - [pool-14-thread-2] [84s 845ms] SocketTube(12) connecting flows
08:07:57.650 DEBUG [SocketTube$InternalReadPublisher.subscribe] - [pool-14-thread-2] [84s 845ms] SocketTube(12) read publisher got subscriber
08:07:57.650 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.signalSubscribe] - [pool-14-thread-2] [84s 845ms] SocketTube(12) registering subscribe event
08:07:57.650 DEBUG [SocketTube.debugState] - [pool-14-thread-2] [84s 845ms] SocketTube(12) leaving read.subscribe: Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
08:07:57.650 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-14-thread-2] [84s 845ms] SocketTube(12) subscribed for writing
08:07:57.650 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.dropSubscription] - [pool-14-thread-2] [84s 845ms] SocketTube(12) write: resetting demand to 0
08:07:57.650 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-14-thread-2] [84s 845ms] SocketTube(12) write: registering startSubscription event
08:07:57.653 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handleSubscribeEvent] - [HttpClient-12-SelectorManager] [84s 848ms] SocketTube(12) subscribe event raised
08:07:57.653 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-12-SelectorManager] [84s 848ms] SocketTube(12) handling pending subscription for CleanupTrigger(SocketTube(12))
08:07:57.653 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.dropSubscription] - [HttpClient-12-SelectorManager] [84s 848ms] Http1AsyncReceiver(SocketTube(12)) Http1TubeSubscriber: dropSubscription
08:07:57.653 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-12-SelectorManager] [84s 848ms] SocketTube(12) read demand reset to 0
08:07:57.653 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-12-SelectorManager] [84s 848ms] SocketTube(12) calling onSubscribe
08:07:57.653 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.request] - [HttpClient-12-SelectorManager] [84s 848ms] SocketTube(12) got some demand for reading
08:07:57.653 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [HttpClient-12-SelectorManager] [84s 848ms] SocketTube(12) resuming read event
08:07:57.653 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-12-SelectorManager] [84s 849ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@672c6c71 for 1 (false)
08:07:57.653 DEBUG [SocketTube.debugState] - [HttpClient-12-SelectorManager] [84s 849ms] SocketTube(12) leaving request(1): Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=0]
08:07:57.653 DEBUG [SocketTube$InternalReadPublisher$ReadSubscription.signalOnSubscribe] - [HttpClient-12-SelectorManager] [84s 849ms] SocketTube(12) onSubscribe called
08:07:57.653 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-12-SelectorManager] [84s 849ms] SocketTube(12) pending subscriber subscribed
08:07:57.653 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-12-SelectorManager] [84s 849ms] SocketTube(12) write: starting subscription
08:07:57.653 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-12-SelectorManager] [84s 849ms] SocketTube(12) write: offloading requestMore
08:07:57.653 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-14-thread-1] [84s 849ms] SocketTube(12) write: requesting more...
08:07:57.653 DEBUG [SocketTube.debugState] - [pool-14-thread-1] [84s 849ms] SocketTube(12) leaving requestMore: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
08:07:57.656 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 852ms] HttpClientImpl(12) next timeout: 0
08:07:57.657 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 852ms] HttpClientImpl(12) next expired: 0
08:07:57.657 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 852ms] HttpClientImpl(12) Next deadline is 3000
08:07:57.661 DEBUG [Http1Response.lambda$readBody$2] - [pool-14-thread-2] [84s 857ms] Http1Response(id=36, PlainHttpConnection(SocketTube(12))) Finished reading body: READING_BODY
08:07:57.662 DEBUG [Http1Response$ClientRefCountTracker.tryRelease] - [pool-14-thread-2] [84s 857ms] Http1Response(id=36, PlainHttpConnection(SocketTube(12))) Operation finished: decrementing ref count for jdk.internal.net.http.HttpClientImpl@57847af8(12)
08:07:57.662 DEBUG [Http1AsyncReceiver.flush] - [pool-14-thread-2] [84s 857ms] Http1AsyncReceiver(SocketTube(12)) Delegate done: 0
08:07:57.662 DEBUG [Http1AsyncReceiver.flush] - [pool-14-thread-2] [84s 857ms] Http1AsyncReceiver(SocketTube(12)) Got 0 bytes for delegate null
08:07:57.663 DEBUG [JdkHttpClient.execute0] - Ending request (DELETE) /session/b431cf96bf9e537172877fa54f061215 in 135ms
08:07:57.663 DEBUG [SeleniumSpanExporter$1.lambda$export$4] - SpanData{spanContext=ImmutableSpanContext{traceId=1d8227c55489824ded05b15ff25d9bad, spanId=0fee7c211cba496e, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=1d8227c55489824ded05b15ff25d9bad, spanId=9df3a1c7e8886a9f, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, 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=1695629277528000000, endEpochNanos=1695629277663300473, attributes=AttributesMap{data={http.method=DELETE, span.kind=client, http.target=/session/b431cf96bf9e537172877fa54f061215, http.status_code=200}, capacity=128, totalAddedValues=4}, totalAttributeCount=4, events=[], totalRecordedEvents=0, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=OK, description=Kind: OK Description:}, hasEnded=true}
08:07:57.664 DEBUG [SeleniumSpanExporter$1.lambda$export$4] - SpanData{spanContext=ImmutableSpanContext{traceId=1d8227c55489824ded05b15ff25d9bad, spanId=51da5c1c2b2f2968, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=1d8227c55489824ded05b15ff25d9bad, spanId=9df3a1c7e8886a9f, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, 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=reverse_proxy, kind=INTERNAL, startEpochNanos=1695629277528000000, endEpochNanos=1695629277663620153, attributes=AttributesMap{data={http.method=DELETE, http.target=/session/b431cf96bf9e537172877fa54f061215, http.status_code=200}, capacity=128, totalAddedValues=3}, totalAttributeCount=3, events=[], totalRecordedEvents=0, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=OK, description=Kind: OK Description:}, hasEnded=true}
08:07:57.664 DEBUG [UrlChecker.waitUntilUnavailable] - Waiting for http://localhost:25209/shutdown
08:07:57.664 DEBUG [UrlChecker.lambda$waitUntilUnavailable$2] - Polling http://localhost:25209/shutdown
08:07:57.665 DEBUG [HttpURLConnection.writeRequests] - sun.net.www.MessageHeader@5a555225 pairs: {GET /shutdown HTTP/1.1: null}{User-Agent: Java/11.0.20.1}{Host: localhost:25209}{Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2}{Connection: keep-alive}
08:07:57.671 DEBUG [HttpURLConnection.getInputStream0] - sun.net.www.MessageHeader@341485913 pairs: {null: HTTP/1.1 200 OK}{Content-Length: 40}{Content-Type: application/json; charset=utf-8}
08:07:57.672 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-12-SelectorManager] [84s 867ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@672c6c71 for 0 (false)
08:07:57.672 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-12-SelectorManager] [84s 867ms] SocketTube(12) got read EOF
08:07:57.672 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.pauseReadEvent] - [HttpClient-12-SelectorManager] [84s 867ms] SocketTube(12) pausing read event
08:07:57.672 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-12-SelectorManager] [84s 867ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@672c6c71 for 0 (false)
08:07:57.672 DEBUG [SocketTube$InternalReadPublisher$ReadSubscription.signalCompletion] - [HttpClient-12-SelectorManager] [84s 867ms] SocketTube(12) completing subscriber
08:07:57.672 DEBUG [ConnectionPool.cleanup] - [HttpClient-12-SelectorManager] [84s 867ms] ConnectionPool(12) SocketTube(12) : ConnectionPool.cleanup(null)
08:07:57.672 DEBUG [PlainHttpConnection.close] - [HttpClient-12-SelectorManager] [84s 867ms] PlainHttpConnection(SocketTube(12)) Closing channel: channel registered with selector, key.interestOps=1, sa.interestOps=1
08:07:57.672 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.signalError] - [HttpClient-12-SelectorManager] [84s 867ms] SocketTube(12) got read error: java.io.IOException: connection closed locally
08:07:57.672 DEBUG [SocketTube.debugState] - [HttpClient-12-SelectorManager] [84s 868ms] SocketTube(12) leaving read() loop after EOF: Reading: [ops=0, demand=0, stopped=true], Writing: [ops=0, demand=1]
08:07:57.672 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-12-SelectorManager] [84s 868ms] SocketTube(12) Read scheduler stopped
08:07:57.672 DEBUG [HttpClientImpl$SelectorAttachment.resetInterestOps] - [HttpClient-12-SelectorManager] [84s 868ms] SelectorAttachment key cancelled for java.nio.channels.SocketChannel[closed]
08:07:57.672 DEBUG [SocketTube$SocketFlowEvent.abort] - [HttpClient-12-SelectorManager] [84s 868ms] SocketTube(12) abort: java.io.IOException: java.nio.channels.CancelledKeyException
08:07:57.672 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 868ms] HttpClientImpl(12) next timeout: 0
08:07:57.672 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 868ms] HttpClientImpl(12) next expired: 0
08:07:57.672 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [84s 868ms] HttpClientImpl(12) Next deadline is 3000
08:07:57.681 DEBUG [UrlChecker.lambda$waitUntilUnavailable$2] - Polling http://localhost:25209/shutdown
08:07:57.707 INFO [SessionSlot.stop] - Stopping session b431cf96bf9e537172877fa54f061215
08:07:57.708 DEBUG [LocalNode.lambda$new$5] - Removing Downloads folder associated with b431cf96bf9e537172877fa54f061215
08:07:57.708 DEBUG [LocalNode.lambda$new$6] - Removing Uploads folder associated with b431cf96bf9e537172877fa54f061215
08:07:57.708 DEBUG [SeleniumSpanExporter$1.lambda$export$4] - SpanData{spanContext=ImmutableSpanContext{traceId=1d8227c55489824ded05b15ff25d9bad, spanId=9df3a1c7e8886a9f, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=1d8227c55489824ded05b15ff25d9bad, spanId=46ee7293f802de85, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, 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=node.forward_command, kind=INTERNAL, startEpochNanos=1695629277527000000, endEpochNanos=1695629277707400569, attributes=AttributesMap{data={http.method=DELETE, random.key=99aad0c9-009e-471a-9fc1-006bfd9f6ad5, span.kind=server, http.target=/session/b431cf96bf9e537172877fa54f061215, http.status_code=200}, capacity=128, totalAddedValues=5}, totalAttributeCount=5, events=[ImmutableEventData{name=HTTP request execution complete, attributes={http.flavor=1, http.handler_class="org.openqa.selenium.remote.http.Route$PredicatedRoute", http.host="10.237.23.122:5454", http.method="DELETE", http.request_content_length="0", http.scheme="HTTP", http.status_code=200, http.target="/session/b431cf96bf9e537172877fa54f061215", http.user_agent="selenium/4.12.0 (python mac)"}, epochNanos=1695629277707389414, totalAttributeCount=9}], totalRecordedEvents=1, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=OK, description=Kind: OK Description:}, hasEnded=true}
08:07:57.708 DEBUG [SeleniumSpanExporter$1.lambda$export$3] - {"traceId": "1d8227c55489824ded05b15ff25d9bad","eventTime": 1695629277707389414,"eventName": "HTTP request execution complete","attributes": {"http.flavor": 1,"http.handler_class": "org.openqa.selenium.remote.http.Route$PredicatedRoute","http.host": "10.237.23.122:5454","http.method": "DELETE","http.request_content_length": "0","http.scheme": "HTTP","http.status_code": 200,"http.target": "\u002fsession\u002fb431cf96bf9e537172877fa54f061215","http.user_agent": "selenium\u002f4.12.0 (python mac)"}}
08:07:58.313 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [85s 508ms] HttpClientImpl(1) next timeout: 0
08:07:58.313 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [85s 508ms] HttpClientImpl(1) next expired: 0
08:07:58.313 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [85s 508ms] HttpClientImpl(1) Next deadline is 3000
08:07:59.868 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-11-SelectorManager] [87s 64ms] HttpClientImpl(11) next timeout: 0
08:07:59.869 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-11-SelectorManager] [87s 64ms] HttpClientImpl(11) next expired: 0
08:07:59.869 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-11-SelectorManager] [87s 64ms] HttpClientImpl(11) Next deadline is 3000
08:08:00.675 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [87s 871ms] HttpClientImpl(12) next timeout: 0
08:08:00.676 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [87s 871ms] HttpClientImpl(12) next expired: 0
08:08:00.676 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-12-SelectorManager] [87s 871ms] HttpClientImpl(12) Next deadline is 3000
08:08:01.316 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [88s 512ms] HttpClientImpl(1) next timeout: 0
08:08:01.316 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [88s 512ms] HttpClientImpl(1) next expired: 0
08:08:01.316 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [88s 512ms] HttpClientImpl(1) Next deadline is 3000
08:08:02.872 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-11-SelectorManager] [90s 67ms] HttpClientImpl(11) next timeout: 0
08:08:02.872 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-11-SelectorManager] [90s 68ms] HttpClientImpl(11) next expired: 0
08:08:02.872 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-11-SelectorManager] [90s 68ms] HttpClientImpl(11) Next deadline is 3000
08:08:02.924 DEBUG [RequestConverter.channelRead0] - Incoming message: DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
POST /se/grid/node/session HTTP/1.1
Connection: Upgrade, HTTP2-Settings
Content-Length: 319
Host: 10.237.23.122:5454
HTTP2-Settings: AAEAAEAAAAIAAAABAAMAAABkAAQBAAAAAAUAAEAA
Upgrade: h2c
traceparent: 00-4171ac478774bd7737a9c7320a977e39-c4d9c6e25420aab5-01
User-Agent: selenium/4.12.1 (java unix)
X-REGISTRATION-SECRET:
08:08:02.924 DEBUG [RequestConverter.channelRead0] - Start of http request: DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
POST /se/grid/node/session HTTP/1.1
Connection: Upgrade, HTTP2-Settings
Content-Length: 319
Host: 10.237.23.122:5454
HTTP2-Settings: AAEAAEAAAAIAAAABAAMAAABkAAQBAAAAAAUAAEAA
Upgrade: h2c
traceparent: 00-4171ac478774bd7737a9c7320a977e39-c4d9c6e25420aab5-01
User-Agent: selenium/4.12.1 (java unix)
X-REGISTRATION-SECRET:
08:08:02.924 DEBUG [RequestConverter.channelRead0] - Incoming message: DefaultLastHttpContent(data: PooledSlicedByteBuf(ridx: 0, widx: 319, cap: 319/319, unwrapped: PooledUnsafeDirectByteBuf(ridx: 650, widx: 650, cap: 1024)), decoderResult: success)
08:08:02.925 DEBUG [RequestConverter.channelRead0] - End of http request: DefaultLastHttpContent(data: PooledSlicedByteBuf(ridx: 319, widx: 319, cap: 319/319, unwrapped: PooledUnsafeDirectByteBuf(ridx: 650, widx: 650, cap: 1024)), decoderResult: success)
08:08:02.925 DEBUG [SpanWrappedHttpHandler.execute] - Wrapping request. Before OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@fdefd3f, context={}, span id=0000000000000000, trace id=00000000000000000000000000000000} and after OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@fdefd3f, context={opentelemetry-trace-span-key=SdkSpan{traceId=4171ac478774bd7737a9c7320a977e39, spanId=ab0d1fc268f4c92b, parentSpanContext=ImmutableSpanContext{traceId=4171ac478774bd7737a9c7320a977e39, spanId=c4d9c6e25420aab5, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, name=node.new_session, kind=INTERNAL, attributes=AttributesMap{data={random.key=f8204ce7-b614-4b05-b533-899ae6cbdda7}, capacity=128, totalAddedValues=1}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1695629282925000000, endEpochNanos=0}}, span id=ab0d1fc268f4c92b, trace id=4171ac478774bd7737a9c7320a977e39}
08:08:02.926 DEBUG [HttpTracing.inject] - Injecting (POST) /se/grid/node/session into OpenTelemetrySpan{traceId=4171ac478774bd7737a9c7320a977e39,spanId=ab0d1fc268f4c92b} at org.openqa.selenium.remote.tracing.SpanWrappedHttpHandler:89
08:08:02.938 DEBUG [SeleniumManager.getBinary] - Selenium Manager binary found at: /tmp/selenium-manager162108532811418711256966606420825087/selenium-manager
08:08:02.939 DEBUG [SeleniumManager.runCommand] - Executing Process: [--browser, chrome, --output, json, --debug]
08:08:02.965 WARN [DriverServiceSessionFactory.apply] - Error while creating session with the driver service. Unable to obtain: Capabilities {browserName: chrome, goog:chromeOptions: {args: [], extensions: []}, networkname:applicationName: RSC, nodename:applicationName: intns07, pageLoadStrategy: normal, platformName: linux, se:noVncPort: 7900, se:vncEnabled: true}, error Failed to run command: [--browser, chrome, --output, json, --debug]
Build info: version: '4.12.1', revision: '8e34639b11'
System info: os.name: 'Linux', os.arch: 'amd64', os.version: '5.10.0-11-amd64', java.version: '11.0.20.1'
Driver info: driver.version: unknown
08:08:02.968 DEBUG [SeleniumSpanExporter$1.lambda$export$4] - SpanData{spanContext=ImmutableSpanContext{traceId=4171ac478774bd7737a9c7320a977e39, spanId=b3c70f02484715ab, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=4171ac478774bd7737a9c7320a977e39, spanId=40de43ba2f28caa5, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, 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=driver_service_factory.apply, kind=INTERNAL, startEpochNanos=1695629282935821963, endEpochNanos=1695629282967248940, attributes=AttributesMap{data={session.capabilities={"browserName": "chrome","goog:chromeOptions": {"extensions": [],"args": []},"networkname:applicationName": "RSC","nodename:applicationName": "intns07","pageLoadStrategy": "normal","platformName": "linux","se:noVncPort": 7900,"se:vncEnabled": true}
, error=true}, capacity=128, totalAddedValues=2}, totalAttributeCount=2, events=[ImmutableEventData{name=exception, attributes={exception.message="Error while creating session with the driver service. Unable to obtain: Capabilities {browserName: chrome, goog:chromeOptions: {args: [], extensions: []}, networkname:applicationName: RSC, nodename:applicationName: intns07, pageLoadStrategy: normal, platformName: linux, se:noVncPort: 7900, se:vncEnabled: true}, error Failed to run command: [--browser, chrome, --output, json, --debug]
Build info: version: '4.12.1', revision: '8e34639b11'
System info: os.name: 'Linux', os.arch: 'amd64', os.version: '5.10.0-11-amd64', java.version: '11.0.20.1'
Driver info: driver.version: unknown", exception.stacktrace="org.openqa.selenium.remote.NoSuchDriverException: Unable to obtain: Capabilities {browserName: chrome, goog:chromeOptions: {args: [], extensions: []}, networkname:applicationName: RSC, nodename:applicationName: intns07, pageLoadStrategy: normal, platformName: linux, se:noVncPort: 7900, se:vncEnabled: true}, error Failed to run command: [--browser, chrome, --output, json, --debug]
Build info: version: '4.12.1', revision: '8e34639b11'
System info: os.name: 'Linux', os.arch: 'amd64', os.version: '5.10.0-11-amd64', java.version: '11.0.20.1'
Driver info: driver.version: unknown
at org.openqa.selenium.remote.service.DriverFinder.getPath(DriverFinder.java:25)
at org.openqa.selenium.remote.service.DriverFinder.getPath(DriverFinder.java:13)
at org.openqa.selenium.grid.node.config.DriverServiceSessionFactory.apply(DriverServiceSessionFactory.java:137)
at org.openqa.selenium.grid.node.config.DriverServiceSessionFactory.apply(DriverServiceSessionFactory.java:73)
at org.openqa.selenium.grid.node.local.SessionSlot.apply(SessionSlot.java:147)
at org.openqa.selenium.grid.node.local.LocalNode.newSession(LocalNode.java:468)
at org.openqa.selenium.grid.node.NewNodeSession.execute(NewNodeSession.java:50)
at org.openqa.selenium.remote.http.Route$TemplatizedRoute.handle(Route.java:193)
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:91)
at org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:63)
at org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:345)
at org.openqa.selenium.remote.http.Route.execute(Route.java:69)
at org.openqa.selenium.grid.node.Node.execute(Node.java:262)
at org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:345)
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: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:829)
Caused by: org.openqa.selenium.WebDriverException: Failed to run command: [--browser, chrome, --output, json, --debug]
Build info: version: '4.12.1', revision: '8e34639b11'
System info: os.name: 'Linux', os.arch: 'amd64', os.version: '5.10.0-11-amd64', java.version: '11.0.20.1'
Driver info: driver.version: unknown
at org.openqa.selenium.manager.SeleniumManager.runCommand(SeleniumManager.java:122)
at org.openqa.selenium.manager.SeleniumManager.getDriverPath(SeleniumManager.java:299)
at org.openqa.selenium.remote.service.DriverFinder.getPath(DriverFinder.java:22)
... 27 more
Caused by: java.lang.IllegalStateException: Actual executable Unable to find executable for: /tmp/selenium-manager162108532811418711256966606420825087/selenium-manager
at org.openqa.selenium.internal.Require$StateChecker.nonNull(Require.java:314)
at org.openqa.selenium.os.OsProcess.<init>(OsProcess.java:65)
at org.openqa.selenium.os.CommandLine.<init>(CommandLine.java:35)
at org.openqa.selenium.manager.SeleniumManager.runCommand(SeleniumManager.java:113)
... 29 more
", exception.type="org.openqa.selenium.remote.NoSuchDriverException", logger="org.openqa.selenium.grid.node.config.DriverServiceSessionFactory", session.capabilities="{"browserName": "chrome","goog:chromeOptions": {"extensions": [],"args": []},"networkname:applicationName": "RSC","nodename:applicationName": "intns07","pageLoadStrategy": "normal","platformName": "linux","se:noVncPort": 7900,"se:vncEnabled": true}
"}, epochNanos=1695629282967063236, totalAttributeCount=5}], totalRecordedEvents=1, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=ERROR, description=Kind: CANCELLED Description:}, hasEnded=true}
08:08:02.978 WARN [SeleniumSpanExporter$1.lambda$export$1] - Error while creating session with the driver service. Unable to obtain: Capabilities {browserName: chrome, goog:chromeOptions: {args: [], extensions: []}, networkname:applicationName: RSC, nodename:applicationName: intns07, pageLoadStrategy: normal, platformName: linux, se:noVncPort: 7900, se:vncEnabled: true}, error Failed to run command: [--browser, chrome, --output, json, --debug]
Build info: version: '4.12.1', revision: '8e34639b11'
System info: os.name: 'Linux', os.arch: 'amd64', os.version: '5.10.0-11-amd64', java.version: '11.0.20.1'
Driver info: driver.version: unknown
08:08:02.980 WARN [SeleniumSpanExporter$1.lambda$export$1] - org.openqa.selenium.remote.NoSuchDriverException: Unable to obtain: Capabilities {browserName: chrome, goog:chromeOptions: {args: [], extensions: []}, networkname:applicationName: RSC, nodename:applicationName: intns07, pageLoadStrategy: normal, platformName: linux, se:noVncPort: 7900, se:vncEnabled: true}, error Failed to run command: [--browser, chrome, --output, json, --debug]
Build info: version: '4.12.1', revision: '8e34639b11'
System info: os.name: 'Linux', os.arch: 'amd64', os.version: '5.10.0-11-amd64', java.version: '11.0.20.1'
Driver info: driver.version: unknown
at org.openqa.selenium.remote.service.DriverFinder.getPath(DriverFinder.java:25)
at org.openqa.selenium.remote.service.DriverFinder.getPath(DriverFinder.java:13)
at org.openqa.selenium.grid.node.config.DriverServiceSessionFactory.apply(DriverServiceSessionFactory.java:137)
at org.openqa.selenium.grid.node.config.DriverServiceSessionFactory.apply(DriverServiceSessionFactory.java:73)
at org.openqa.selenium.grid.node.local.SessionSlot.apply(SessionSlot.java:147)
at org.openqa.selenium.grid.node.local.LocalNode.newSession(LocalNode.java:468)
at org.openqa.selenium.grid.node.NewNodeSession.execute(NewNodeSession.java:50)
at org.openqa.selenium.remote.http.Route$TemplatizedRoute.handle(Route.java:193)
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:91)
at org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:63)
at org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:345)
at org.openqa.selenium.remote.http.Route.execute(Route.java:69)
at org.openqa.selenium.grid.node.Node.execute(Node.java:262)
at org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:345)
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: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:829)
Caused by: org.openqa.selenium.WebDriverException: Failed to run command: [--browser, chrome, --output, json, --debug]
Build info: version: '4.12.1', revision: '8e34639b11'
System info: os.name: 'Linux', os.arch: 'amd64', os.version: '5.10.0-11-amd64', java.version: '11.0.20.1'
Driver info: driver.version: unknown
at org.openqa.selenium.manager.SeleniumManager.runCommand(SeleniumManager.java:122)
at org.openqa.selenium.manager.SeleniumManager.getDriverPath(SeleniumManager.java:299)
at org.openqa.selenium.remote.service.DriverFinder.getPath(DriverFinder.java:22)
... 27 more
Caused by: java.lang.IllegalStateException: Actual executable Unable to find executable for: /tmp/selenium-manager162108532811418711256966606420825087/selenium-manager
at org.openqa.selenium.internal.Require$StateChecker.nonNull(Require.java:314)
at org.openqa.selenium.os.OsProcess.<init>(OsProcess.java:65)
at org.openqa.selenium.os.CommandLine.<init>(CommandLine.java:35)
at org.openqa.selenium.manager.SeleniumManager.runCommand(SeleniumManager.java:113)
... 29 more
08:08:02.981 WARN [SeleniumSpanExporter$1.lambda$export$3] - {"traceId": "4171ac478774bd7737a9c7320a977e39","eventTime": 1695629282967063236,"eventName": "exception","attributes": {"exception.message": "Error while creating session with the driver service. Unable to obtain: Capabilities {browserName: chrome, goog:chromeOptions: {args: [], extensions: []}, networkname:applicationName: RSC, nodename:applicationName: intns07, pageLoadStrategy: normal, platformName: linux, se:noVncPort: 7900, se:vncEnabled: true}, error Failed to run command: [--browser, chrome, --output, json, --debug]\nBuild info: version: '4.12.1', revision: '8e34639b11'\nSystem info: os.name: 'Linux', os.arch: 'amd64', os.version: '5.10.0-11-amd64', java.version: '11.0.20.1'\nDriver info: driver.version: unknown","exception.stacktrace": "org.openqa.selenium.remote.NoSuchDriverException: Unable to obtain: Capabilities {browserName: chrome, goog:chromeOptions: {args: [], extensions: []}, networkname:applicationName: RSC, nodename:applicationName: intns07, pageLoadStrategy: normal, platformName: linux, se:noVncPort: 7900, se:vncEnabled: true}, error Failed to run command: [--browser, chrome, --output, json, --debug]\nBuild info: version: '4.12.1', revision: '8e34639b11'\nSystem info: os.name: 'Linux', os.arch: 'amd64', os.version: '5.10.0-11-amd64', java.version: '11.0.20.1'\nDriver info: driver.version: unknown\n\tat org.openqa.selenium.remote.service.DriverFinder.getPath(DriverFinder.java:25)\n\tat org.openqa.selenium.remote.service.DriverFinder.getPath(DriverFinder.java:13)\n\tat org.openqa.selenium.grid.node.config.DriverServiceSessionFactory.apply(DriverServiceSessionFactory.java:137)\n\tat org.openqa.selenium.grid.node.config.DriverServiceSessionFactory.apply(DriverServiceSessionFactory.java:73)\n\tat org.openqa.selenium.grid.node.local.SessionSlot.apply(SessionSlot.java:147)\n\tat org.openqa.selenium.grid.node.local.LocalNode.newSession(LocalNode.java:468)\n\tat org.openqa.selenium.grid.node.NewNodeSession.execute(NewNodeSession.java:50)\n\tat org.openqa.selenium.remote.http.Route$TemplatizedRoute.handle(Route.java:193)\n\tat org.openqa.selenium.remote.http.Route.execute(Route.java:69)\n\tat org.openqa.selenium.grid.security.RequiresSecretFilter.lambda$apply$0(RequiresSecretFilter.java:62)\n\tat org.openqa.selenium.remote.tracing.SpanWrappedHttpHandler.execute(SpanWrappedHttpHandler.java:91)\n\tat org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:63)\n\tat org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:345)\n\tat org.openqa.selenium.remote.http.Route.execute(Route.java:69)\n\tat org.openqa.selenium.grid.node.Node.execute(Node.java:262)\n\tat org.openqa.selenium.remote.http.Route$CombinedRoute.handle(Route.java:345)\n\tat org.openqa.selenium.remote.http.Route.execute(Route.java:69)\n\tat org.openqa.selenium.remote.AddWebDriverSpecHeaders.lambda$apply$0(AddWebDriverSpecHeaders.java:35)\n\tat org.openqa.selenium.remote.ErrorFilter.lambda$apply$0(ErrorFilter.java:44)\n\tat org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:63)\n\tat org.openqa.selenium.remote.ErrorFilter.lambda$apply$0(ErrorFilter.java:44)\n\tat org.openqa.selenium.remote.http.Filter$1.execute(Filter.java:63)\n\tat org.openqa.selenium.netty.server.SeleniumHandler.lambda$channelRead0$0(SeleniumHandler.java:44)\n\tat java.base\u002fjava.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)\n\tat java.base\u002fjava.util.concurrent.FutureTask.run(FutureTask.java:264)\n\tat java.base\u002fjava.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)\n\tat java.base\u002fjava.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)\n\tat java.base\u002fjava.lang.Thread.run(Thread.java:829)\nCaused by: org.openqa.selenium.WebDriverException: Failed to run command: [--browser, chrome, --output, json, --debug]\nBuild info: version: '4.12.1', revision: '8e34639b11'\nSystem info: os.name: 'Linux', os.arch: 'amd64', os.version: '5.10.0-11-amd64', java.version: '11.0.20.1'\nDriver info: driver.version: unknown\n\tat org.openqa.selenium.manager.SeleniumManager.runCommand(SeleniumManager.java:122)\n\tat org.openqa.selenium.manager.SeleniumManager.getDriverPath(SeleniumManager.java:299)\n\tat org.openqa.selenium.remote.service.DriverFinder.getPath(DriverFinder.java:22)\n\t... 27 more\nCaused by: java.lang.IllegalStateException: Actual executable Unable to find executable for: \u002ftmp\u002fselenium-manager162108532811418711256966606420825087\u002fselenium-manager\n\tat org.openqa.selenium.internal.Require$StateChecker.nonNull(Require.java:314)\n\tat org.openqa.selenium.os.OsProcess.\u003cinit>(OsProcess.java:65)\n\tat org.openqa.selenium.os.CommandLine.\u003cinit>(CommandLine.java:35)\n\tat org.openqa.selenium.manager.SeleniumManager.runCommand(SeleniumManager.java:113)\n\t... 29 more\n","exception.type": "org.openqa.selenium.remote.NoSuchDriverException","logger": "org.openqa.selenium.grid.node.config.DriverServiceSessionFactory","session.capabilities": "{\"browserName\": \"chrome\",\"goog:chromeOptions\": {\"extensions\": [],\"args\": []},\"networkname:applicationName\": \"RSC\",\"nodename:applicationName\": \"intns07\",\"pageLoadStrategy\": \"normal\",\"platformName\": \"linux\",\"se:noVncPort\": 7900,\"se:vncEnabled\": true}\n"}}
08:08:02.991 DEBUG [SeleniumSpanExporter$1.lambda$export$4] - SpanData{spanContext=ImmutableSpanContext{traceId=4171ac478774bd7737a9c7320a977e39, spanId=40de43ba2f28caa5, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=4171ac478774bd7737a9c7320a977e39, spanId=ab0d1fc268f4c92b, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, 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=node.new_session, kind=INTERNAL, startEpochNanos=1695629282933741324, endEpochNanos=1695629282991076111, attributes=AttributesMap{data={error=true, current.session.count=0}, capacity=128, totalAddedValues=2}, totalAttributeCount=2, events=[ImmutableEventData{name=Unable to create session with the driver, attributes={current.session.count=0, logger="org.openqa.selenium.grid.node.local.LocalNode", session.request.capabilities="Capabilities {browserName: chrome, goog:chromeOptions: {args: [], extensions: []}, networkname:applicationName: RSC, pageLoadStrategy: normal, platformName: linux}", session.request.downstreamdialect="[W3C]"}, epochNanos=1695629282991058653, totalAttributeCount=4}], totalRecordedEvents=1, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=ERROR, description=Kind: ABORTED Description:}, hasEnded=true}
08:08:02.998 WARN [SeleniumSpanExporter$1.lambda$export$3] - {"traceId": "4171ac478774bd7737a9c7320a977e39","eventTime": 1695629282991058653,"eventName": "Unable to create session with the driver","attributes": {"current.session.count": 0,"logger": "org.openqa.selenium.grid.node.local.LocalNode","session.request.capabilities": "Capabilities {browserName: chrome, goog:chromeOptions: {args: [], extensions: []}, networkname:applicationName: RSC, pageLoadStrategy: normal, platformName: linux}","session.request.downstreamdialect": "[W3C]"}}
08:08:03.016 DEBUG [SeleniumSpanExporter$1.lambda$export$4] - SpanData{spanContext=ImmutableSpanContext{traceId=4171ac478774bd7737a9c7320a977e39, spanId=ab0d1fc268f4c92b, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=4171ac478774bd7737a9c7320a977e39, spanId=c4d9c6e25420aab5, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, 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=node.new_session, kind=INTERNAL, startEpochNanos=1695629282925000000, endEpochNanos=1695629283015277454, attributes=AttributesMap{data={http.method=POST, random.key=f8204ce7-b614-4b05-b533-899ae6cbdda7, span.kind=server, http.target=/se/grid/node/session, http.status_code=200}, capacity=128, totalAddedValues=5}, totalAttributeCount=5, events=[ImmutableEventData{name=HTTP request execution complete, attributes={http.flavor=1, http.handler_class="org.openqa.selenium.grid.security.RequiresSecretFilter$$Lambda$503/0x0000000840262840", http.host="10.237.23.122:5454", http.method="POST", http.request_content_length="319", http.scheme="HTTP", http.status_code=200, http.target="/se/grid/node/session", http.user_agent="selenium/4.12.1 (java unix)"}, epochNanos=1695629283015263144, totalAttributeCount=9}], totalRecordedEvents=1, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=OK, description=Kind: OK Description:}, hasEnded=true}
08:08:03.020 DEBUG [SeleniumSpanExporter$1.lambda$export$3] - {"traceId": "4171ac478774bd7737a9c7320a977e39","eventTime": 1695629283015263144,"eventName": "HTTP request execution complete","attributes": {"http.flavor": 1,"http.handler_class": "org.openqa.selenium.grid.security.RequiresSecretFilter$$Lambda$503\u002f0x0000000840262840","http.host": "10.237.23.122:5454","http.method": "POST","http.request_content_length": "319","http.scheme": "HTTP","http.status_code": 200,"http.target": "\u002fse\u002fgrid\u002fnode\u002fsession","http.user_agent": "selenium\u002f4.12.1 (java unix)"}}
08:08:03.679 DEBUG [HttpClientImpl$SelectorManager.shutdown] - [HttpClient-12-SelectorManager] [90s 874ms] HttpClientImpl(12) SelectorManager shutting down
08:08:03.679 DEBUG [Http2ClientImpl.stop] - [HttpClient-12-SelectorManager] [90s 875ms] Http2ClientImpl stopping |
|
Looks like it is working fine twice, then fails the third time 6 seconds later. @diemol any idea why this changes? The temp file should continue to be there so long as the Java process that started the node is present, right? |
|
it is working fine more or less 30 time. |
|
Hello @titusfortner , Trying to create manually folder : /tmp/selenium-manager22615714154407388062558993830215611 Any folder own by seluser user is removed after 2 minutes. |
|
@bonigarcia I'm assuming this is a grid thing and you don't know any more than I do why it might happen? |
|
I'm not sure if this is a Grid thing. Perhaps it is a Java thing (definitively not Rust). For some reason, it seems the Selenium Manager in the temporal folder is deleted after some time, and not when JVM is shut down. I don't know if this is caused because of Docker. In any case, a possible solution to the problem is to uncompress SM to the cache folder (at least in Java), as was initially planned for 4.13.0. Are we doing that for 4.14.0? |
|
I think this issue makes a good case for it. Lets update #11359 and merge it. |
|
Can you share how you are starting the Grid? Are you using the most recent version? Can you share the Grid logs when it starts? |
eravion
changed the title
|
Hello @diemol Yes, this issue is still here with version 4.13, it start with version 4.11 (no issue with 4.10). I don't think it is linked to grid, something is removing any folder in /tmp/ own by seluser after a while. |
8 tasks
|
I just upgraded grid and nodes to 4.14.1 from 4.11 and i think that we started to get this error. In a testsuite with 400 scenarios, randomly 4-5 attempts to start a new browser ends up with a log like this: |
I still need to understand your environment. Where is that test being executed? Plus my questions in this comment. @parholmdahl same story, we need a way to reproduce this, otherwise we will end up closing the issue. |
|
I will do my best to describe our environment: Selenium HUB 4.14.1 (selenium/hub:4.14) with 4 nodes (based on selenium/node-base:4.14) running different browsers (modded image to install chrome, edge and firefox and adding mtls certificates). All this running in a kubernetes kluster. Then running tests from a jenkinsserver (Cucumber - with Selenium Ruby). Randomly (not doing the same action like logging in only, or uploading file only.. Randomly) we started to get this error after upgrade. This can be found in HUB logs: This can be found in Node log: |
|
I am experiencing the same issue with Selenium Grid from version 4.11 onwards. My infrastructure is in Kubernetes also. I tested the same infra but using Selenium Grid 4.10 instead, and works just perfectly, the issue is I can't use that version because of a critical vulnerability. So I'm wondering what changed now we are having this error the moment the grid tries to create session. |
|
Helo @diemol Our configuration : Variable : hub host ip : 10.10.10.10 node host ip : 10.10.10.11 ** config.toml file** [server] [node] [[node.driver-configuration]] Script python to test from selenium import webdriver chrome_options = webdriver.ChromeOptions() |
|
I'm going to close this as complete from #11359 |
|
This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs. |
Sign up for free
to subscribe to this conversation on GitHub.
Already have an account?
Sign in.
What happened?
Hello,
Since version 4.11 we have issue with the capabilities.
Maybe something linked to this update #12169 ?
How can we reproduce the issue?
Relevant log output
Operating System
Docker 4.11 -> 4.12.1
Selenium version
4.11 -> 4.12.1
What are the browser(s) and version(s) where you see this issue?
issue with Firefox and Chrome on 4.11 -> 4.12.1
What are the browser driver(s) and version(s) where you see this issue?
embedded in the docker
Are you using Selenium Grid?
4.12.1
The text was updated successfully, but these errors were encountered: