search

SeleniumHQ / selenium

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

[🐛 Bug]: file upload command did not work with Firefox 122 #13534

Closed lacell75 closed 8 months ago

lacell75 commented 8 months ago

What happened?

It's impossible to use file Selenium Standalone command with Firefox ver. 122 image. We have an error Error: HTTP method not allowed

How can we reproduce the issue?

Launch a selenium standalone docker: 
`docker run -p 4444:4444 -v /dev/shm:/dev/shm selenium/standalone-firefox:122`

Execute a script that uses file command:
https://webdriver.io/docs/api/selenium/#file

I can provide a minimal nodejs project to reproduce this issue if necessary

example with webdriverIO:
    import path from 'node:path'

    it('should upload a file', async () => {
        await browser.url('https://the-internet.herokuapp.com/upload')

        const filePath = '/path/to/some/file.png'
        const remoteFilePath = await browser.uploadFile(filePath) -> Error HTTP method not allowed

        await $('#file-upload').setValue(remoteFilePath)
        await $('#file-submit').click()
    });
 * </example>

No error on marionnette logs:

1706718549574   geckodriver::marionette DEBUG   Connection to Marionette established on 127.0.0.1:61242.
1706718551648   webdriver::server       DEBUG   <- 200 OK {"value":{"sessionId":"c3a4894b-bac0-4ccd-a0ee-bba65b2bf2a0","capabilities":{"acceptInsecureCerts":true,"browserNam ... ctability":false,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"unhandledPromptBehavior":"dismiss and notify"}}}
1706718560076   webdriver::server       DEBUG   -> POST /session/c3a4894b-bac0-4ccd-a0ee-bba65b2bf2a0/url {"url":"https://the-internet.herokuapp.com/upload/"}
1706718561328   webdriver::server       DEBUG   <- 200 OK {"value":null}

### Relevant log output

```shell
POST /session/2e933d5f-a7fc-4192-9a84-5896941d34a7/file HTTP/1.1
Connection: Upgrade, HTTP2-Settings
Content-Length: 2547
Host: 172.24.128.1:5555
HTTP2-Settings: AAEAAEAAAAIAAAABAAMAAABkAAQBAAAAAAUAAEAA
Upgrade: h2c
accept: application/json
accept-encoding: gzip, deflate, br
Cache-Control: no-cache
content-type: application/json; charset=utf-8
traceparent: 00-600ca47e05d5f0156dbf161db73a1597-495c6509cb4233ba-01
user-agent: webdriver/8.29.1
16:38:22.949 DEBUG [RequestConverter.channelRead0] - Start of http request: DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
POST /session/2e933d5f-a7fc-4192-9a84-5896941d34a7/file HTTP/1.1
Connection: Upgrade, HTTP2-Settings
Content-Length: 2547
Host: 172.24.128.1:5555
HTTP2-Settings: AAEAAEAAAAIAAAABAAMAAABkAAQBAAAAAAUAAEAA
Upgrade: h2c
accept: application/json
accept-encoding: gzip, deflate, br
Cache-Control: no-cache
content-type: application/json; charset=utf-8
traceparent: 00-600ca47e05d5f0156dbf161db73a1597-495c6509cb4233ba-01
user-agent: webdriver/8.29.1
16:38:22.951 DEBUG [RequestConverter.channelRead0] - Incoming message: DefaultHttpContent(data: PooledSlicedByteBuf(ridx: 0, widx: 1590, cap: 1590/1590, unwrapped: PooledUnsafeDirectByteBuf(ridx: 2048, widx: 2048, cap: 2048)), decoderResult: success)
16:38:22.955 DEBUG [RequestConverter.channelRead0] - Incoming message: DefaultLastHttpContent(data: PooledSlicedByteBuf(ridx: 0, widx: 957, cap: 957/957, unwrapped: PooledUnsafeDirectByteBuf(ridx: 957, widx: 957, cap: 32768)), decoderResult: success)
16:38:22.965 DEBUG [RequestConverter.channelRead0] - End of http request: DefaultLastHttpContent(data: PooledSlicedByteBuf(ridx: 957, widx: 957, cap: 957/957, unwrapped: PooledUnsafeDirectByteBuf(ridx: 957, widx: 957, cap: 32768)), decoderResult: success)
16:38:22.968 DEBUG [SpanWrappedHttpHandler.execute] - Wrapping request. Before OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@1d76aeea, context={}, span id=0000000000000000, trace id=00000000000000000000000000000000} and after OpenTelemetryContext{tracer=io.opentelemetry.sdk.trace.SdkTracer@1d76aeea, context={opentelemetry-trace-span-key=SdkSpan{traceId=600ca47e05d5f0156dbf161db73a1597, spanId=1d0dd0958f532eba, parentSpanContext=ImmutableSpanContext{traceId=600ca47e05d5f0156dbf161db73a1597, spanId=495c6509cb4233ba, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, name=node.forward_command, kind=INTERNAL, attributes=AttributesMap{data={random.key=59443bdf-6651-4b6b-83dd-aa4c8316d8c6}, capacity=128, totalAddedValues=1}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1706715502968000000, endEpochNanos=0}}, span id=1d0dd0958f532eba, trace id=600ca47e05d5f0156dbf161db73a1597}
16:38:22.969 DEBUG [HttpTracing.inject] - Injecting (POST) /session/2e933d5f-a7fc-4192-9a84-5896941d34a7/file into OpenTelemetrySpan{traceId=600ca47e05d5f0156dbf161db73a1597,spanId=1d0dd0958f532eba} at org.openqa.selenium.remote.tracing.SpanWrappedHttpHandler:85
16:38:22.970 DEBUG [JdkHttpClient.execute0] - Executing request: (POST) /session/2e933d5f-a7fc-4192-9a84-5896941d34a7/file
16:38:22.971 DEBUG [HttpClientImpl.sendAsync] - [pool-2-thread-3] [14s 297ms] HttpClientImpl(1) ClientImpl (async) send http://localhost:21693/session/2e933d5f-a7fc-4192-9a84-5896941d34a7/file POST
16:38:22.972 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [14s 298ms] HttpClientImpl(1) next timeout: 300000
16:38:22.972 DEBUG [Exchange.establishExchange] - [pool-3-thread-2] [14s 298ms] Exchange establishing exchange for http://localhost:21693/session/2e933d5f-a7fc-4192-9a84-5896941d34a7/file POST,
         proxy=null
16:38:22.973 DEBUG [Http2ClientImpl.getConnectionFor] - [pool-3-thread-2] [14s 299ms] Http2ClientImpl not found in connection pool
16:38:22.973 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [14s 299ms] HttpClientImpl(1) next expired: 1199028
16:38:22.973 DEBUG [ExchangeImpl.get] - [pool-3-thread-2] [14s 299ms] ExchangeImpl get: Trying to get HTTP/2 connection
16:38:22.973 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [14s 300ms] HttpClientImpl(1) Next deadline is 3000
16:38:22.974 DEBUG [ExchangeImpl.createExchangeImpl] - [pool-3-thread-2] [14s 300ms] ExchangeImpl handling HTTP/2 connection creation result
16:38:22.974 DEBUG [ExchangeImpl.createExchangeImpl] - [pool-3-thread-2] [14s 300ms] ExchangeImpl new Http1Exchange, try to upgrade
16:38:22.975 DEBUG [HttpConnection.getConnection] - [pool-3-thread-2] [14s 301ms] HttpConnection(SocketTube(?)) SocketTube(1): plain connection retrieved from HTTP/1.1 pool
16:38:22.975 DEBUG [Exchange.checkFor407] - [pool-3-thread-2] [14s 301ms] Exchange checkFor407: all clear
16:38:22.976 DEBUG [Http1Exchange.sendHeadersAsync] - [pool-3-thread-2] [14s 302ms] Http1Exchange Sending headers only
16:38:22.976 DEBUG [Http1AsyncReceiver.subscribe] - [pool-3-thread-2] [14s 302ms] Http1AsyncReceiver(SocketTube(1)) Subscribed pending jdk.internal.net.http.Http1Response$HeadersReader@30f9ece1 queue.isEmpty: true
16:38:22.976 DEBUG [Http1AsyncReceiver.handlePendingDelegate] - [pool-3-thread-2] [14s 303ms] Http1AsyncReceiver(SocketTube(1)) delegate is now jdk.internal.net.http.Http1Response$HeadersReader@30f9ece1, demand=1, canRequestMore=true, queue.isEmpty=true
16:38:22.977 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-3-thread-2] [14s 303ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 1
16:38:22.977 DEBUG [Http1AsyncReceiver.checkRequestMore] - [pool-3-thread-2] [14s 303ms] Http1AsyncReceiver(SocketTube(1)) checkRequestMore: canRequestMore=true, hasDemand=true
16:38:22.978 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-3-thread-2] [14s 304ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 1
16:38:22.978 DEBUG [Http1AsyncReceiver.checkRequestMore] - [pool-3-thread-2] [14s 304ms] Http1AsyncReceiver(SocketTube(1)) checkRequestMore: canRequestMore=true, hasDemand=true
16:38:22.979 DEBUG [Http1Exchange.sendHeadersAsync] - [pool-3-thread-2] [14s 305ms] Http1Exchange response created in advance
16:38:22.979 DEBUG [Http1Exchange.connectFlows] - [pool-3-thread-2] [14s 305ms] Http1Exchange SocketTube(1) connecting flows
16:38:22.980 DEBUG [SocketTube.connectFlows] - [pool-3-thread-2] [14s 306ms] SocketTube(1) connecting flows
16:38:22.980 DEBUG [SocketTube$InternalReadPublisher.subscribe] - [pool-3-thread-2] [14s 306ms] SocketTube(1) read publisher got subscriber
16:38:22.980 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.signalSubscribe] - [pool-3-thread-2] [14s 306ms] SocketTube(1) registering subscribe event
16:38:22.981 DEBUG [SocketTube.debugState] - [pool-3-thread-2] [14s 307ms] SocketTube(1) leaving read.subscribe:  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
16:38:22.981 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handleSubscribeEvent] - [HttpClient-1-SelectorManager] [14s 307ms] SocketTube(1) subscribe event raised
16:38:22.981 DEBUG [Http1Exchange$Http1Publisher.subscribe] - [pool-3-thread-2] [14s 307ms] Http1Publisher(SocketTube(1)) got subscriber: SocketTube(1)
16:38:22.981 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-1-SelectorManager] [14s 307ms] SocketTube(1) handling pending subscription for jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber@2cf2d285
16:38:22.981 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-3-thread-2] [14s 307ms] SocketTube(1) subscribed for writing
16:38:22.982 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-1-SelectorManager] [14s 308ms] SocketTube(1) read demand reset to 0
16:38:22.997 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.dropSubscription] - [pool-3-thread-2] [14s 323ms] SocketTube(1) write: resetting demand to 0
16:38:22.997 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-1-SelectorManager] [14s 323ms] SocketTube(1) calling onSubscribe
16:38:22.997 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-3-thread-2] [14s 324ms] SocketTube(1) write: registering startSubscription event
16:38:22.998 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.onSubscribe] - [HttpClient-1-SelectorManager] [14s 324ms] Http1AsyncReceiver(SocketTube(1)) Received onSubscribed from upstream
16:38:22.998 DEBUG [Http1Exchange.lambda$sendHeadersAsync$4] - [pool-3-thread-2] [14s 324ms] Http1Exchange requestAction.headers
16:38:22.998 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-3-thread-1] [14s 324ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 1
16:38:22.998 DEBUG [SocketTube$InternalReadPublisher$ReadSubscription.signalOnSubscribe] - [HttpClient-1-SelectorManager] [14s 324ms] SocketTube(1) onSubscribe called
16:38:22.999 DEBUG [Http1AsyncReceiver.checkRequestMore] - [pool-3-thread-1] [14s 325ms] Http1AsyncReceiver(SocketTube(1)) checkRequestMore: canRequestMore=true, hasDemand=true
16:38:22.999 DEBUG [Http1Exchange.lambda$sendHeadersAsync$4] - [pool-3-thread-2] [14s 325ms] Http1Exchange setting outgoing with headers
16:38:22.999 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.requestMore] - [pool-3-thread-1] [14s 325ms] Http1AsyncReceiver(SocketTube(1)) Http1TubeSubscriber: requesting one more from upstream
16:38:22.999 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-1-SelectorManager] [14s 325ms] SocketTube(1) pending subscriber subscribed
16:38:23.000 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.request] - [pool-3-thread-1] [14s 326ms] SocketTube(1) got some demand for reading
16:38:23.000 DEBUG [Http1Exchange.appendToOutgoing] - [pool-3-thread-2] [14s 326ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=456 cap=456]], throwable=null]
16:38:23.000 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [pool-3-thread-1] [14s 327ms] SocketTube(1) resuming read event
16:38:23.000 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [14s 326ms] HttpClientImpl(1) next timeout: 299972
16:38:23.001 DEBUG [SocketTube.debugState] - [pool-3-thread-1] [14s 327ms] SocketTube(1) leaving request(1):  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=0]
16:38:23.001 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-3-thread-2] [14s 327ms] Http1Publisher(SocketTube(1)) WriteTask
16:38:23.001 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [14s 327ms] HttpClientImpl(1) next expired: 0
16:38:23.002 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-3-thread-2] [14s 328ms] Http1Publisher(SocketTube(1)) hasOutgoing = true
16:38:23.002 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [14s 328ms] HttpClientImpl(1) Next deadline is 3000
16:38:23.003 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-1-SelectorManager] [14s 329ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@44b4199e for 1 (false)
16:38:23.003 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-1-SelectorManager] [14s 329ms] SocketTube(1) write: starting subscription
16:38:23.003 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-1-SelectorManager] [14s 330ms] SocketTube(1) write: offloading requestMore
16:38:23.004 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-3-thread-2] [14s 330ms] SocketTube(1) write: requesting more...
16:38:23.004 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [14s 330ms] HttpClientImpl(1) next timeout: 299968
16:38:23.004 DEBUG [Http1Exchange$Http1Publisher$Http1WriteSubscription.request] - [pool-3-thread-2] [14s 330ms] Http1Publisher(SocketTube(1)) subscription request(1), demand=1
16:38:23.005 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-3-thread-2] [14s 331ms] Http1Publisher(SocketTube(1)) WriteTask
16:38:23.005 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-3-thread-2] [14s 331ms] Http1Publisher(SocketTube(1)) hasOutgoing = true
16:38:23.005 DEBUG [Http1Exchange.getOutgoing] - [pool-3-thread-2] [14s 331ms] Http1Exchange initiating completion of headersSentCF
16:38:23.005 DEBUG [Exchange.checkFor407] - [pool-3-thread-2] [14s 331ms] Exchange checkFor407: all clear
16:38:23.004 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [14s 331ms] HttpClientImpl(1) next expired: 0
16:38:23.006 DEBUG [Exchange.sendRequestBody] - [pool-3-thread-2] [14s 332ms] Exchange sendRequestBody
16:38:23.006 DEBUG [Http1Exchange.sendBodyAsync] - [pool-3-thread-2] [14s 332ms] Http1Exchange sendBodyAsync
16:38:23.006 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [14s 332ms] HttpClientImpl(1) Next deadline is 3000
16:38:23.006 DEBUG [Http1Exchange.sendBodyAsync] - [pool-3-thread-2] [14s 332ms] Http1Exchange bodySubscriber is class jdk.internal.net.http.Http1Request$FixedContentSubscriber
16:38:23.007 DEBUG [Http1Exchange.requestMoreBody] - [pool-3-thread-2] [14s 333ms] Http1Exchange requesting more request body from the subscriber
16:38:23.007 DEBUG [Http1Exchange$Http1BodySubscriber.request] - [pool-3-thread-2] [14s 333ms] jdk.internal.net.http.Http1Request@3baae09d Http1BodySubscriber requesting 1, from jdk.internal.net.http.PullPublisher$Subscription@425b856d
16:38:23.007 DEBUG [Http1Request$FixedContentSubscriber.onNext] - [pool-3-thread-2] [14s 334ms] jdk.internal.net.http.Http1Request@3baae09d onNext
16:38:23.008 DEBUG [Http1Exchange.appendToOutgoing] - [pool-3-thread-2] [14s 334ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=2547 cap=16384]], throwable=null]
16:38:23.008 DEBUG [Http1Request$FixedContentSubscriber.onComplete] - [pool-3-thread-2] [14s 334ms] jdk.internal.net.http.Http1Request@3baae09d onComplete
16:38:23.008 DEBUG [Http1Exchange.appendToOutgoing] - [pool-3-thread-2] [14s 334ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=0 cap=0]], throwable=null]
16:38:23.009 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-3-thread-2] [14s 335ms] Http1Publisher(SocketTube(1)) onNext with 456 bytes
16:38:23.009 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [pool-3-thread-2] [14s 335ms] SocketTube(1) trying to write: 456
16:38:23.010 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [pool-3-thread-2] [14s 336ms] SocketTube(1) wrote: 456
16:38:23.010 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-3-thread-2] [14s 336ms] SocketTube(1) write: requesting more...
16:38:23.010 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-1-SelectorManager] [14s 336ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@44b4199e for 0 (false)
16:38:23.010 DEBUG [Http1Exchange$Http1Publisher$Http1WriteSubscription.request] - [pool-3-thread-2] [14s 337ms] Http1Publisher(SocketTube(1)) subscription request(1), demand=1
16:38:23.011 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-1-SelectorManager] [14s 337ms] SocketTube(1) read bytes: 156
16:38:23.011 DEBUG [SocketTube.debugState] - [pool-3-thread-2] [14s 337ms] SocketTube(1) leaving requestMore:  Reading: [ops=0, demand=0, stopped=false], Writing: [ops=0, demand=1]
16:38:23.011 DEBUG [Http1AsyncReceiver.asyncReceive] - [HttpClient-1-SelectorManager] [14s 337ms] Http1AsyncReceiver(SocketTube(1)) Putting 156 bytes into the queue
16:38:23.011 DEBUG [SocketTube.debugState] - [pool-3-thread-2] [14s 338ms] SocketTube(1) leaving w.onNext Reading: [ops=0, demand=0, stopped=false], Writing: [ops=0, demand=1]
16:38:23.012 DEBUG [Http1AsyncReceiver.flush] - [pool-3-thread-1] [14s 338ms] Http1AsyncReceiver(SocketTube(1)) Got 156 bytes for delegate jdk.internal.net.http.Http1Response$HeadersReader@30f9ece1
16:38:23.012 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [HttpClient-1-SelectorManager] [14s 338ms] SocketTube(1) resuming read event
16:38:23.013 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-3-thread-1] [14s 339ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 1
16:38:23.012 DEBUG [Http1Exchange.requestMoreBody] - [pool-3-thread-2] [14s 338ms] Http1Exchange requesting more request body from the subscriber
16:38:23.032 DEBUG [Http1AsyncReceiver.flush] - [pool-3-thread-1] [14s 358ms] Http1AsyncReceiver(SocketTube(1)) Forwarding 156 bytes to delegate jdk.internal.net.http.Http1Response$HeadersReader@30f9ece1
16:38:23.031 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-1-SelectorManager] [14s 358ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@44b4199e for 1 (false)
16:38:23.032 DEBUG [Http1Response$HeadersReader.handle] - [pool-3-thread-1] [14s 358ms] Http1Response(id=3, PlainHttpConnection(SocketTube(1))) Sending 156/156 bytes to header parser
16:38:23.032 DEBUG [Http1Exchange$Http1BodySubscriber.request] - [pool-3-thread-2] [14s 358ms] jdk.internal.net.http.Http1Request@3baae09d Http1BodySubscriber requesting 1, from jdk.internal.net.http.PullPublisher$Subscription@425b856d
16:38:23.033 DEBUG [Http1Response$HeadersReader.handle] - [pool-3-thread-1] [14s 359ms] Http1Response(id=3, PlainHttpConnection(SocketTube(1))) Parsing headers completed. bytes=133
16:38:23.032 DEBUG [SocketTube.debugState] - [HttpClient-1-SelectorManager] [14s 359ms] SocketTube(1) leaving read() loop after onNext:  Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
16:38:23.033 DEBUG [Http1AsyncReceiver.unsubscribe] - [pool-3-thread-1] [14s 360ms] Http1AsyncReceiver(SocketTube(1)) Unsubscribed jdk.internal.net.http.Http1Response$HeadersReader@30f9ece1
16:38:23.033 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-3-thread-2] [14s 359ms] Http1Publisher(SocketTube(1)) onNext with 2547 bytes
16:38:23.034 DEBUG [Http1AsyncReceiver.flush] - [pool-3-thread-1] [14s 360ms] Http1AsyncReceiver(SocketTube(1)) Delegate done: 23
16:38:23.034 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [14s 360ms] HttpClientImpl(1) next timeout: 299938
16:38:23.034 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [pool-3-thread-2] [14s 361ms] SocketTube(1) trying to write: 2547
16:38:23.035 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [14s 361ms] HttpClientImpl(1) next expired: 0
16:38:23.035 DEBUG [SocketTube$InternalWriteSubscriber.tryFlushCurrent] - [pool-3-thread-2] [14s 362ms] SocketTube(1) wrote: 2547
16:38:23.035 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [14s 362ms] HttpClientImpl(1) Next deadline is 3000
16:38:23.036 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.requestMore] - [pool-3-thread-2] [14s 362ms] SocketTube(1) write: requesting more...
16:38:23.036 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-1-SelectorManager] [14s 362ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@44b4199e for 0 (false)
16:38:23.036 DEBUG [Http1Exchange$Http1Publisher$Http1WriteSubscription.request] - [pool-3-thread-2] [14s 362ms] Http1Publisher(SocketTube(1)) subscription request(1), demand=1
16:38:23.036 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-1-SelectorManager] [14s 363ms] SocketTube(1) no more demand for reading
16:38:23.037 DEBUG [SocketTube.debugState] - [pool-3-thread-2] [14s 363ms] SocketTube(1) leaving requestMore:  Reading: [ops=0, demand=0, stopped=false], Writing: [ops=0, demand=1]
16:38:23.037 DEBUG [SocketTube.debugState] - [pool-3-thread-2] [14s 363ms] SocketTube(1) leaving w.onNext Reading: [ops=0, demand=0, stopped=false], Writing: [ops=0, demand=1]
16:38:23.037 DEBUG [Http1Exchange.getOutgoing] - [pool-3-thread-2] [14s 363ms] Http1Exchange initiating completion of bodySentCF
16:38:23.037 DEBUG [SocketTube.debugState] - [HttpClient-1-SelectorManager] [14s 363ms] SocketTube(1) leaving read() loop with no demand Reading: [ops=0, demand=0, stopped=false], Writing: [ops=0, demand=1]
16:38:23.038 DEBUG [Utils.lambda$wrapForDebug$9] - [pool-3-thread-2] [14s 364ms] Http1Exchange sendBodyAsync completed successfully
16:38:23.038 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [14s 364ms] HttpClientImpl(1) next timeout: 299934
16:38:23.038 DEBUG [Http1Exchange.getResponseAsync] - [pool-3-thread-2] [14s 364ms] Http1Exchange reading headers
16:38:23.038 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [14s 364ms] HttpClientImpl(1) next expired: 0
16:38:23.039 DEBUG [Http1Response.readHeadersAsync] - [pool-3-thread-2] [14s 365ms] Http1Response(id=3, PlainHttpConnection(SocketTube(1))) Reading Headers: (remaining: 23) READING_BODY
16:38:23.039 DEBUG [Http1Response.readHeadersAsync] - [pool-3-thread-2] [14s 365ms] Http1Response(id=3, PlainHttpConnection(SocketTube(1))) First time around
16:38:23.039 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [14s 365ms] HttpClientImpl(1) Next deadline is 3000
16:38:23.039 DEBUG [Http1Response.readHeadersAsync] - [pool-3-thread-2] [14s 366ms] Http1Response(id=3, PlainHttpConnection(SocketTube(1))) headersReader is already completed
16:38:23.040 DEBUG [Http1Response.lambda$readHeadersAsync$0] - [pool-3-thread-2] [14s 366ms] Http1Response(id=3, PlainHttpConnection(SocketTube(1))) Reading Headers: creating Response object; state is now READING_BODY
16:38:23.040 DEBUG [Utils.lambda$wrapForDebug$9] - [pool-3-thread-2] [14s 366ms] Http1Exchange getResponseAsync completed successfully
16:38:23.040 DEBUG [Http1Response.readBody] - [pool-3-thread-2] [14s 367ms] Http1Response(id=3, PlainHttpConnection(SocketTube(1))) readBody: return2Cache: true
16:38:23.041 DEBUG [Http1Response$ClientRefCountTracker.acquire] - [pool-3-thread-2] [14s 367ms] Http1Response(id=3, PlainHttpConnection(SocketTube(1))) Operation started: incrementing ref count for jdk.internal.net.http.HttpClientImpl@3a519eaf(1)
16:38:23.041 DEBUG [Http1AsyncReceiver.subscribe] - [pool-3-thread-2] [14s 367ms] Http1AsyncReceiver(SocketTube(1)) Subscribed pending jdk.internal.net.http.Http1Response$BodyReader@1e0c5e43/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@61ed3787 queue.isEmpty: false
16:38:23.041 DEBUG [ResponseContent$FixedLengthBodyParser.onSubscribe] - [pool-3-thread-2] [14s 368ms] PlainHttpConnection(SocketTube(1))/ResponseContent/FixedLengthBodyParser length=23, onSubscribe: jdk.internal.net.http.Http1Response$Http1BodySubscriber
16:38:23.042 DEBUG [Http1AsyncReceiver.handlePendingDelegate] - [pool-3-thread-2] [14s 368ms] Http1AsyncReceiver(SocketTube(1)) delegate is now jdk.internal.net.http.Http1Response$BodyReader@1e0c5e43/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@61ed3787, demand=9223372036854775807, canRequestMore=false, queue.isEmpty=false
16:38:23.042 DEBUG [Http1AsyncReceiver.flush] - [pool-3-thread-2] [14s 368ms] Http1AsyncReceiver(SocketTube(1)) Got 23 bytes for delegate jdk.internal.net.http.Http1Response$BodyReader@1e0c5e43/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@61ed3787
16:38:23.043 DEBUG [Http1AsyncReceiver.hasDemand] - [pool-3-thread-2] [14s 369ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 9223372036854775807
16:38:23.043 DEBUG [Http1AsyncReceiver.flush] - [pool-3-thread-2] [14s 369ms] Http1AsyncReceiver(SocketTube(1)) Forwarding 23 bytes to delegate jdk.internal.net.http.Http1Response$BodyReader@1e0c5e43/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@61ed3787
16:38:23.043 DEBUG [Http1Response$BodyReader.handle] - [pool-3-thread-2] [14s 369ms] Http1Response(id=3, PlainHttpConnection(SocketTube(1))) Sending 23/156 bytes to body parser
16:38:23.043 DEBUG [ResponseContent$FixedLengthBodyParser.accept] - [pool-3-thread-2] [14s 369ms] PlainHttpConnection(SocketTube(1))/ResponseContent/FixedLengthBodyParser Parser got 23 bytes (23 remaining / 23)
16:38:23.044 DEBUG [ResponseContent$FixedLengthBodyParser.accept] - [pool-3-thread-2] [14s 370ms] PlainHttpConnection(SocketTube(1))/ResponseContent/FixedLengthBodyParser Parser got all expected bytes: completing
16:38:23.044 DEBUG [Http1AsyncReceiver.clear] - [pool-3-thread-2] [14s 370ms] Http1AsyncReceiver(SocketTube(1)) cleared
16:38:23.044 DEBUG [Http1Response.onFinished] - [pool-3-thread-2] [14s 370ms] Http1Response(id=3, PlainHttpConnection(SocketTube(1))) SocketTube(1): return to HTTP/1.1 pool
16:38:23.044 DEBUG [ConnectionPool.registerCleanupTrigger] - [pool-3-thread-2] [14s 371ms] ConnectionPool(1) registering CleanupTrigger(SocketTube(1))
16:38:23.045 DEBUG [SocketTube.connectFlows] - [pool-3-thread-2] [14s 371ms] SocketTube(1) connecting flows
16:38:23.064 DEBUG [SocketTube$InternalReadPublisher.subscribe] - [pool-3-thread-2] [14s 390ms] SocketTube(1) read publisher got subscriber
16:38:23.065 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.signalSubscribe] - [pool-3-thread-2] [14s 391ms] SocketTube(1) registering subscribe event
16:38:23.065 DEBUG [SocketTube.debugState] - [pool-3-thread-2] [14s 391ms] SocketTube(1) leaving read.subscribe:  Reading: [ops=0, demand=0, stopped=false], Writing: [ops=0, demand=1]
16:38:23.065 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-3-thread-2] [14s 391ms] SocketTube(1) subscribed for writing
16:38:23.065 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handleSubscribeEvent] - [HttpClient-1-SelectorManager] [14s 391ms] SocketTube(1) subscribe event raised
16:38:23.066 DEBUG [SocketTube$InternalWriteSubscriber$WriteSubscription.dropSubscription] - [pool-3-thread-2] [14s 392ms] SocketTube(1) write: resetting demand to 0
16:38:23.066 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-1-SelectorManager] [14s 392ms] SocketTube(1) handling pending subscription for CleanupTrigger(SocketTube(1))
16:38:23.066 DEBUG [Http1AsyncReceiver$Http1TubeSubscriber.dropSubscription] - [HttpClient-1-SelectorManager] [14s 393ms] Http1AsyncReceiver(SocketTube(1)) Http1TubeSubscriber: dropSubscription
16:38:23.066 DEBUG [SocketTube$InternalWriteSubscriber.onSubscribe] - [pool-3-thread-2] [14s 392ms] SocketTube(1) write: registering startSubscription event
16:38:23.067 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-1-SelectorManager] [14s 393ms] SocketTube(1) read demand reset to 0
16:38:23.067 DEBUG [Http1AsyncReceiver.flush] - [pool-3-thread-2] [14s 393ms] Http1AsyncReceiver(SocketTube(1)) Delegate done: 0
16:38:23.067 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.handlePending] - [HttpClient-1-SelectorManager] [14s 394ms] SocketTube(1) calling onSubscribe
16:38:23.068 DEBUG [Http1AsyncReceiver.flush] - [pool-3-thread-2] [14s 394ms] Http1AsyncReceiver(SocketTube(1)) Got 0 bytes for delegate null
16:38:23.068 DEBUG [Http1Response.lambda$readBody$2] - [pool-3-thread-2] [14s 394ms] Http1Response(id=3, PlainHttpConnection(SocketTube(1))) Finished reading body: READING_BODY
16:38:23.068 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.request] - [HttpClient-1-SelectorManager] [14s 394ms] SocketTube(1) got some demand for reading
16:38:23.069 DEBUG [Http1Response$ClientRefCountTracker.tryRelease] - [pool-3-thread-2] [14s 395ms] Http1Response(id=3, PlainHttpConnection(SocketTube(1))) Operation finished: decrementing ref count for jdk.internal.net.http.HttpClientImpl@3a519eaf(1)
16:38:23.069 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.resumeReadEvent] - [HttpClient-1-SelectorManager] [14s 395ms] SocketTube(1) resuming read event
16:38:23.069 DEBUG [Http1Exchange$Http1Publisher$WriteTask.run] - [pool-3-thread-2] [14s 395ms] Http1Publisher(SocketTube(1)) completed, stopping jdk.internal.net.http.common.SequentialScheduler@13411f4f
16:38:23.069 DEBUG [JdkHttpClient.execute0] - Ending request (POST) /session/2e933d5f-a7fc-4192-9a84-5896941d34a7/file in 98ms
16:38:23.069 DEBUG [HttpClientImpl$SelectorAttachment.register] - [HttpClient-1-SelectorManager] [14s 396ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@44b4199e for 1 (true)
16:38:23.070 DEBUG [SeleniumSpanExporter$1.lambda$export$4] - SpanData{spanContext=ImmutableSpanContext{traceId=600ca47e05d5f0156dbf161db73a1597, spanId=98b5dd2624e24aff, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=600ca47e05d5f0156dbf161db73a1597, spanId=1d0dd0958f532eba, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, resource=Resource{schemaUrl=null, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.34.1"}}, instrumentationScopeInfo=InstrumentationScopeInfo{name=default, version=null, schemaUrl=null, attributes={}}, name=httpclient.execute, kind=INTERNAL, startEpochNanos=1706715502970000000, endEpochNanos=1706715503069638400, attributes=AttributesMap{data={span.kind=client, http.target=/session/2e933d5f-a7fc-4192-9a84-5896941d34a7/file, http.status_code=405, http.method=POST}, capacity=128, totalAddedValues=4}, totalAttributeCount=4, events=[], totalRecordedEvents=0, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=ERROR, description=Kind: INVALID_ARGUMENT Description:}, hasEnded=true}
16:38:23.070 DEBUG [SocketTube.debugState] - [pool-3-thread-2] [14s 396ms] SocketTube(1) leaving requestMore:  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=0]
16:38:23.071 DEBUG [SeleniumSpanExporter$1.lambda$export$4] - SpanData{spanContext=ImmutableSpanContext{traceId=600ca47e05d5f0156dbf161db73a1597, spanId=b6bb6620eea545ab, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=600ca47e05d5f0156dbf161db73a1597, spanId=1d0dd0958f532eba, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, resource=Resource{schemaUrl=null, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.34.1"}}, instrumentationScopeInfo=InstrumentationScopeInfo{name=default, version=null, schemaUrl=null, attributes={}}, name=reverse_proxy, kind=INTERNAL, startEpochNanos=1706715502970000000, endEpochNanos=1706715503071172500, attributes=AttributesMap{data={http.target=/session/2e933d5f-a7fc-4192-9a84-5896941d34a7/file, http.status_code=405, http.method=POST}, capacity=128, totalAddedValues=3}, totalAttributeCount=3, events=[], totalRecordedEvents=0, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=ERROR, description=Kind: INVALID_ARGUMENT Description:}, hasEnded=true}
16:38:23.070 DEBUG [SocketTube.debugState] - [HttpClient-1-SelectorManager] [14s 396ms] SocketTube(1) leaving request(1):  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=0]
16:38:23.072 DEBUG [SocketTube$InternalReadPublisher$ReadSubscription.signalOnSubscribe] - [HttpClient-1-SelectorManager] [14s 398ms] SocketTube(1) onSubscribe called
16:38:23.072 DEBUG [SeleniumSpanExporter$1.lambda$export$4] - SpanData{spanContext=ImmutableSpanContext{traceId=600ca47e05d5f0156dbf161db73a1597, spanId=1d0dd0958f532eba, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=600ca47e05d5f0156dbf161db73a1597, spanId=495c6509cb4233ba, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=true, valid=true}, resource=Resource{schemaUrl=null, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.34.1"}}, instrumentationScopeInfo=InstrumentationScopeInfo{name=default, version=null, schemaUrl=null, attributes={}}, name=node.forward_command, kind=INTERNAL, startEpochNanos=1706715502968000000, endEpochNanos=1706715503072506900, attributes=AttributesMap{data={span.kind=server, http.target=/session/2e933d5f-a7fc-4192-9a84-5896941d34a7/file, http.status_code=405, random.key=59443bdf-6651-4b6b-83dd-aa4c8316d8c6, http.method=POST}, 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="172.24.128.1:5555", http.method="POST", http.request_content_length="2547", http.scheme="HTTP", http.status_code=405, http.target="/session/2e933d5f-a7fc-4192-9a84-5896941d34a7/file", http.user_agent="webdriver/8.29.1"}, epochNanos=1706715503072500200, totalAttributeCount=9}], totalRecordedEvents=1, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=ERROR, description=Kind: INVALID_ARGUMENT Description:}, hasEnded=true}
16:38:23.072 DEBUG [SocketTube$InternalReadPublisher$InternalReadSubscription.read] - [HttpClient-1-SelectorManager] [14s 399ms] SocketTube(1) pending subscriber subscribed
16:38:23.074 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [14s 400ms] HttpClientImpl(1) next timeout: 0
16:38:23.074 WARN [SeleniumSpanExporter$1.lambda$export$3] - {"traceId": "600ca47e05d5f0156dbf161db73a1597","eventTime": 1706715503072500200,"eventName": "HTTP request execution complete","attributes": {"http.flavor": 1,"http.handler_class": "org.openqa.selenium.remote.http.Route$PredicatedRoute","http.host": "172.24.128.1:5555","http.method": "POST","http.request_content_length": "2547","http.scheme": "HTTP","http.status_code": 405,"http.target": "\u002fsession\u002f2e933d5f-a7fc-4192-9a84-5896941d34a7\u002ffile","http.user_agent": "webdriver\u002f8.29.1"}}

16:38:23.074 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [14s 400ms] HttpClientImpl(1) next expired: 1199926
16:38:23.075 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [14s 401ms] HttpClientImpl(1) Next deadline is 3000
16:38:23.075 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-1-SelectorManager] [14s 401ms] SocketTube(1) write: starting subscription
16:38:23.075 DEBUG [SocketTube$InternalWriteSubscriber.startSubscription] - [HttpClient-1-SelectorManager] [14s 401ms] SocketTube(1) write: offloading requestMore
16:38:23.076 DEBUG [HttpClientImpl$SelectorManager.run] - [HttpClient-1-SelectorManager] [14s 402ms] HttpClientImpl(1) next timeout: 0

Operating System

linux/Windows

Selenium version

4.17.0

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

firefox 122

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

Geckodriver 0.34.0

Are you using Selenium Grid?

No response

github-actions[bot] commented 8 months ago

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

Info for maintainers

Triage this issue by using labels.

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

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

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

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

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

Thank you!

titusfortner commented 8 months ago

This is not the valid w3c endpoint /session/2e933d5f-a7fc-4192-9a84-5896941d34a7/file HTTP/1.1

It needs to be /se/file in Selenium 4. https://github.com/SeleniumHQ/selenium/blob/selenium-4.17.0/javascript/node/selenium-webdriver/lib/http.js#L364

Raise an issue with wdio

lacell75 commented 8 months ago

This is not the valid w3c endpoint /session/2e933d5f-a7fc-4192-9a84-5896941d34a7/file HTTP/1.1

Thanks a lot for your feedback

github-actions[bot] commented 7 months ago

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.