SeleniumHQ / selenium

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

[🐛 Bug]: "System.IO.IOException : Cannot access a closed stream" when disposing DevToolsSession #14466

Closed arnonax-tr closed 18 hours ago

arnonax-tr commented 2 months ago

What happened?

This bug happens pretty rarely, but it does. I ran the following test with [Repeat(1000)] to reproduce it:

using System.Collections.Concurrent;
using OpenQA.Selenium.Chrome;
using OpenQA.Selenium.DevTools;
using OpenQA.Selenium.DevTools.V127;
using OpenQA.Selenium.DevTools.V127.Network;
using OpenQA.Selenium.DevTools.V127.Fetch;
using EnableCommandSettings = OpenQA.Selenium.DevTools.V127.Fetch.EnableCommandSettings;
using RequestPattern = OpenQA.Selenium.DevTools.V127.Fetch.RequestPattern;

namespace TestProject2;

internal class DevToolsIssue
{
    private static bool _disposing;
    private static int _repeatCounter;

    [Test, Repeat(1000)]
    public void EventHandlersCanRunAfterDevToolsIsDisposed()
    {
        TestContext.Progress.WriteLine($"Repeat={_repeatCounter++}");
        _disposing = false;

        var executingHandlers = new CountdownEvent(1);

        using var driver = new ChromeDriver();
        var caughtExceptions = new ConcurrentQueue<Exception>();

        using (var devToolsSession = driver.GetDevToolsSession(new DevToolsOptions { ProtocolVersion = 127 }))
        {
            var networkAdapter = new NetworkAdapter(devToolsSession);
            var fetch = new FetchAdapter(devToolsSession);
            var network = new V127Network(networkAdapter, fetch);

            var enableCommandSettings = new EnableCommandSettings
            {
                Patterns = new RequestPattern[]
                {
                    new()
                    {
                        RequestStage = RequestStage.Request,
                        UrlPattern = "*"
                    }
                }
            };
            fetch.Enable(enableCommandSettings);

            network.RequestPaused += async (_, args) =>
            {
                if (!executingHandlers.TryAddCount())
                    return;

                try
                {
                    // Do some stuff...
                    await TestContext.Progress.WriteLineAsync($"ContinueRequestWithoutModification when _disposing={_disposing}");
                    await network.ContinueRequestWithoutModification(args.RequestData);
                }
                catch (Exception ex)
                {
                    caughtExceptions.Enqueue(ex);
                }
                finally
                {
                    executingHandlers.Signal();
                }
            };

            driver.Url = "https://www.google.com";

            executingHandlers.Signal();
            executingHandlers.Wait();

        } // Disposing DevToolsSession

        if (!caughtExceptions.IsEmpty)
            throw new AggregateException(caughtExceptions);
    }
}

And I got the following exception:

System.IO.IOException : Cannot access a closed stream.
   at System.Net.Http.HttpConnection.RawConnectionStream.WriteAsync(ReadOnlyMemory`1 buffer, CancellationToken cancellationToken)
   at System.Net.WebSockets.ManagedWebSocket.SendFrameLockAcquiredNonCancelableAsync(MessageOpcode opcode, Boolean endOfMessage, Boolean disableCompression, ReadOnlyMemory`1 payloadBuffer)
   at System.Net.WebSockets.ManagedWebSocket.SendFrameAsync(MessageOpcode opcode, Boolean endOfMessage, Boolean disableCompression, ReadOnlyMemory`1 payloadBuffer, CancellationToken cancellationToken)
   at System.Net.WebSockets.ManagedWebSocket.SendCloseFrameAsync(WebSocketCloseStatus closeStatus, String closeStatusDescription, CancellationToken cancellationToken)
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at System.Net.WebSockets.ManagedWebSocket.SendCloseFrameAsync(WebSocketCloseStatus closeStatus, String closeStatusDescription, CancellationToken cancellationToken)
   at System.Net.WebSockets.ManagedWebSocket.CloseOutputAsyncCore(WebSocketCloseStatus closeStatus, String statusDescription, CancellationToken cancellationToken)
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at System.Net.WebSockets.ManagedWebSocket.CloseOutputAsyncCore(WebSocketCloseStatus closeStatus, String statusDescription, CancellationToken cancellationToken)
   at System.Net.WebSockets.ManagedWebSocket.CloseOutputAsync(WebSocketCloseStatus closeStatus, String statusDescription, CancellationToken cancellationToken)
   at System.Net.WebSockets.ClientWebSocket.CloseOutputAsync(WebSocketCloseStatus closeStatus, String statusDescription, CancellationToken cancellationToken)
   at OpenQA.Selenium.DevTools.WebSocketConnection.ReceiveData()
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
   at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining)
   at System.Threading.Tasks.Task.RunContinuations(Object continuationObject)
   at System.Threading.Tasks.Task`1.TrySetResult(TResult result)
   at System.Threading.Tasks.ValueTask`1.ValueTaskSourceAsTask.<>c.<.cctor>b__4_0(Object state)
   at System.Net.WebSockets.ManagedWebSocket.ReceiveAsyncPrivate[TResult](Memory`1 payloadBuffer, CancellationToken cancellationToken)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Net.WebSockets.ManagedWebSocket.EnsureBufferContainsAsync(Int32 minimumRequiredBytes, CancellationToken cancellationToken, Boolean throwOnPrematureClosure)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining)
   at System.Threading.Tasks.Task.RunContinuations(Object continuationObject)
   at System.Threading.Tasks.Task`1.TrySetResult(TResult result)
   at System.Net.Http.HttpConnection.RawConnectionStream.ReadAsync(Memory`1 buffer, CancellationToken cancellationToken)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
   at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining)
   at System.Threading.Tasks.Task.RunContinuations(Object continuationObject)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.SetExistingTaskResult(Task`1 task, TResult result)
   at System.Net.Http.HttpConnection.ReadBufferedAsyncCore(Memory`1 destination)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.InvokeContinuation(Action`1 continuation, Object state, Boolean forceAsync, Boolean requiresExecutionContextFlow)
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.OnCompleted(SocketAsyncEventArgs _)
   at System.Threading._IOCompletionCallback.PerformIOCompletionCallback(UInt32 errorCode, UInt32 numBytes, NativeOverlapped* pNativeOverlapped)
--- End of stack trace from previous location ---
   at System.Net.WebSockets.ManagedWebSocket.SendCloseFrameAsync(WebSocketCloseStatus closeStatus, String closeStatusDescription, CancellationToken cancellationToken)
   at System.Net.WebSockets.ManagedWebSocket.CloseOutputAsyncCore(WebSocketCloseStatus closeStatus, String statusDescription, CancellationToken cancellationToken)
   at OpenQA.Selenium.DevTools.WebSocketConnection.ReceiveData()
   at OpenQA.Selenium.DevTools.WebSocketConnection.<Start>b__22_0()
   at OpenQA.Selenium.DevTools.WebSocketConnection.Stop()
   at OpenQA.Selenium.DevTools.DevToolsSession.TerminateSocketConnection()
   at OpenQA.Selenium.DevTools.DevToolsSession.<Dispose>b__43_0()
   at OpenQA.Selenium.DevTools.DevToolsSession.Dispose(Boolean disposing)
   at OpenQA.Selenium.DevTools.DevToolsSession.Dispose()
   at TestProject2.DevToolsIssue.EventHandlersCanRunAfterDevToolsIsDisposed()

How can we reproduce the issue?

Just paste the above code to a new nUnit project and run the test.

Relevant log output

14:19:20.338 TRACE SeleniumManager: Driver path: chromedriver.EXE
14:19:20.338 TRACE SeleniumManager: Browser path: C:\Program Files\Google\Chrome\Application\chrome.exe
14:19:20.864 DEBUG HttpCommandExecutor: Executing command: []: newSession {"capabilities":{"firstMatch":[{"browserName":"chrome","goog:chromeOptions":{"binary":"C:\\Program Files\\Google\\Chrome\\Application\\chrome.exe"}}]}}
14:19:20.864 TRACE HttpCommandExecutor: >> Method: POST, RequestUri: 'http://localhost:52938/session', Version: 1.1, Content: System.Net.Http.ByteArrayContent, Headers:
{
  Accept: application/json; charset=utf-8
  User-Agent: selenium/4.23.0
  User-Agent: (.net windows)
  Content-Type: application/json; charset=utf-8
  Content-Length: 151
}
{"capabilities":{"firstMatch":[{"browserName":"chrome","goog:chromeOptions":{"binary":"C:\\Program Files\\Google\\Chrome\\Application\\chrome.exe"}}]}}
14:19:21.677 TRACE HttpCommandExecutor: << StatusCode: 200, ReasonPhrase: 'OK', Version: 1.1, Content: System.Net.Http.HttpConnectionResponseContent, Headers:
{
  Cache-Control: no-cache
  Content-Length: 883
  Content-Type: application/json; charset=utf-8
}
14:19:21.678 DEBUG HttpCommandExecutor: Response: (3eb6914a3922045bf8e623a3e8dc17bc Success: System.Collections.Generic.Dictionary`2[System.String,System.Object])
14:19:25.763 DEBUG HttpCommandExecutor: Executing command: [3eb6914a3922045bf8e623a3e8dc17bc]: get {"url":"https://www.google.com"}
14:19:25.763 TRACE HttpCommandExecutor: >> Method: POST, RequestUri: 'http://localhost:52938/session/3eb6914a3922045bf8e623a3e8dc17bc/url', Version: 1.1, Content: System.Net.Http.ByteArrayContent, Headers:
{
  Accept: application/json; charset=utf-8
  User-Agent: selenium/4.23.0
  User-Agent: (.net windows)
  Content-Type: application/json; charset=utf-8
  Content-Length: 32
}
{"url":"https://www.google.com"}
14:19:26.371 TRACE HttpCommandExecutor: << StatusCode: 200, ReasonPhrase: 'OK', Version: 1.1, Content: System.Net.Http.HttpConnectionResponseContent, Headers:
{
  Cache-Control: no-cache
  Content-Length: 14
  Content-Type: application/json; charset=utf-8
}
14:19:26.371 DEBUG HttpCommandExecutor: Response: ( Success: )
14:19:26.388 DEBUG HttpCommandExecutor: Executing command: [3eb6914a3922045bf8e623a3e8dc17bc]: quit {}
14:19:26.389 TRACE HttpCommandExecutor: >> Method: DELETE, RequestUri: 'http://localhost:52938/session/3eb6914a3922045bf8e623a3e8dc17bc', Version: 1.1, Content: <null>, Headers:
{
  User-Agent: selenium/4.23.0
  User-Agent: (.net windows)
  Accept: application/json
  Accept: image/png
}
14:19:26.491 TRACE HttpCommandExecutor: << StatusCode: 200, ReasonPhrase: 'OK', Version: 1.1, Content: System.Net.Http.HttpConnectionResponseContent, Headers:
{
  Cache-Control: no-cache
  Content-Length: 14
  Content-Type: application/json; charset=utf-8
}
14:19:26.491 DEBUG HttpCommandExecutor: Response: ( Success: )

Operating System

Windows 11

Selenium version

C# 11 (dotnet 8), Selenium.WebDriver 4.23.0

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

Chrome 128

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

ChromeDriver 128.0.6613.8600

Are you using Selenium Grid?

No response

github-actions[bot] commented 2 months ago

@arnonax-tr, 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!

nvborisenko commented 2 months ago

This issue is obvious.

network.RequestPaused += async (_, args) =>
{
  await network.ContinueRequestWithoutModification(args.RequestData);
}

which may lead to System.IO.IOException : Cannot access a closed stream.

It happens because your async event handler is invoked in background, while main execution program is continuing. And there is a chance that main execution flow disposes driver earlier than your network.ContinueRequestWithoutModification(args.RequestData).

This situation is fixed in new BiDi approach (https://github.com/SeleniumHQ/selenium/pull/14318). I have no ideas how to fix it.

Probably making your event handler sync can help (at least please try):

network.RequestPaused += (_, args) =>
{
  Task.Run(async () => await network.ContinueRequestWithoutModification(args.RequestData));
}

EDITED: You may prove my theory via adding a delay in your async handler like await Task.Delay(5_000) before invocation of network.Continue....

arnonax-tr commented 2 months ago

And there is a chance that main execution flow disposes driver earlier than your network.ContinueRequestWithoutModification(args.RequestData).

I don't think so. That's exactly the reason I added the CountdownEvent object (executingHandlers). This should ensure that I'm not disposing the driver (or even the DevToolsSession) before all event handlers are done. (Or if they just start after dispose has already started, they immediately exit due to the if (!executingHandlers.TryAddCount()) statement)

arnonax-tr commented 2 months ago

Regarding the BiDi approach: do you have an ETA for when it will be available? Also I'll be grateful if you can provide an example of how my code should look like with that approach.

nvborisenko commented 2 months ago

That's exactly the reason I added the CountdownEvent object (executingHandlers)

Your event handler is async void, selenium invokes (actually schedules your delegate in TaskScheduler to be invoked), and we don't know when exactly your handler is actually invoked. Moreover, in selenium we really fire and forget event handlers. This is design issue, which may lead to unexpected behavior in race conditions. This design issue is addressed in BiDi implementation (or at least should be addressed).

No ETA, PR is under review.

arnonax-tr commented 1 month ago

Regarding the BiDi approach: do you have an ETA for when it will be available? Also I'll be grateful if you can provide an example of how my code should look like with that approach.

I saw that the Bidi PR was merged to trunk. Does it mean that it will be available in the next release?

Also, are there examples or documentation on how to use it for capturing and manipulating network traffic?

nvborisenko commented 1 month ago

There is nightly builds you can try right now: https://github.com/SeleniumHQ/selenium/pkgs/nuget/Selenium.WebDriver

Documentation is not available yet, hopefully the following code may help you to get started:

var context = await driver.AsBidirectionalContextAsync();

await context.Network.OnBeforeRequestSentAsync(e => Console.WriteLine(e));

await context.NavigateAsync("https://selenium.dev", new() { Wait = ReadinessState.Complete });

await context.Network.InterceptRequestAsync(async e => await e.Request.Request.FailAsync());
diemol commented 18 hours ago

I will close this as the issue has not had any more activity.