[🐛 Bug]: LogContext does not work when created asynchronously

[MJB222398]

What happened?

I have an NUnit testing solution and I want to collect driver logs per test on the file system. I create a new driver for each test, doing this asynchronously. So my solution was to create a new ILogContext when I do this and use a FileLogHandler with a file path for that test. However I noticed that these log files were almost empty, whatever the tests did with the driver was not being logged.

Eventually I figured out it was because I am creating it asynchronously, if I do it synchronously then all the logs are present in the file.

How can we reproduce the issue?

using OpenQA.Selenium;
using OpenQA.Selenium.Edge;
using OpenQA.Selenium.Internal.Logging;
using OpenQA.Selenium.Remote;

namespace SeleniumPlayground
{
    public class Tests
    {
        private const string SeleniumHubUrl = "http://localhost:4444/wd/hub";
        private const string LogFilePathTest1 = "C:\\Users\\MyName\\Downloads\\Gubbins\\logs-test-1.log";
        private const string LogFilePathTest2 = "C:\\Users\\MyName\\Downloads\\Gubbins\\logs-test-2.log";

        private class MyDriver(IWebDriver driver, ILogContext logContext) : IDisposable
        {
            private readonly IWebDriver _driver = driver;
            private readonly ILogContext _logContext = logContext;

            public void Navigate(string url) => _driver.Navigate().GoToUrl(url);

            public void Dispose()
            {
                _logContext?.Dispose();
                _driver?.Dispose();
            }
        }

        [Test]
        public async Task Test1()
        {
            using var myDriver = CreateDriver(LogFilePathTest1);

            await DoSomeDriverActions(myDriver);
        }

        [Test]
        public async Task Test2()
        {
            using var myDriver = await CreateDriverAsync(LogFilePathTest2);

            await DoSomeDriverActions(myDriver);
        }

        private static async Task DoSomeDriverActions(MyDriver driver)
        {
            driver.Navigate("https://www.amazon.co.uk/");
            await Task.Delay(2000);
            driver.Navigate("https://www.bbc.co.uk/");
            await Task.Delay(2000);
            driver.Navigate("https://www.ebay.co.uk/");
            await Task.Delay(2000);
        }

        private static MyDriver CreateDriver(string logFilePath)
        {
            var logContext = Log.CreateContext(LogEventLevel.Trace).Handlers.Add(new FileLogHandler(logFilePath));
            var driver = new RemoteWebDriver(new Uri(SeleniumHubUrl), GetDriverCapabilities(), TimeSpan.FromSeconds(30));

            return new MyDriver(driver, logContext);
        }

        private static async Task<MyDriver> CreateDriverAsync(string logFilePath)
        {
            var logContext = Log.CreateContext(LogEventLevel.Trace).Handlers.Add(new FileLogHandler(logFilePath));
            var driver = new RemoteWebDriver(new Uri(SeleniumHubUrl), GetDriverCapabilities(), TimeSpan.FromSeconds(30));

            await Task.Delay(100);

            return new MyDriver(driver, logContext);
        }

        private static ICapabilities GetDriverCapabilities()
        {
            EdgeOptions edgeOptions = new();
            edgeOptions.AddArgument("--start-maximized");
            edgeOptions.AddArgument("--disable-dev-shm-usage");
            return edgeOptions.ToCapabilities();
        }
    }
}

So if you run the tests above you see that Test1 produces a log file with all expected logs. Test2 does not, the only difference between the two tests is that one creates the driver in a synchronous method and the other does it asynchronously.

Relevant log output

N/A

Operating System

Windows 10

Selenium version

4.19.0

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

All

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

All

Are you using Selenium Grid?

Yes

[github-actions]

@MJB222398, 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]

To simplify the example to reproduce the issue:

using OpenQA.Selenium;
using OpenQA.Selenium.Chrome;
using OpenQA.Selenium.Internal.Logging;

namespace SeleniumPlayground
{
    public class Tests
    {
        private class MyDriver(IWebDriver driver, ILogContext logContext) : IDisposable
        {
            private readonly IWebDriver _driver = driver;
            private readonly ILogContext _logContext = logContext;

            public void Navigate(string url) => _driver.Navigate().GoToUrl(url);

            public void Dispose()
            {
                _logContext?.Dispose();
                _driver?.Dispose();
            }
        }

        [Test]
        public async Task Test2()
        {
            using var driver = await CreateDriverAsync();

            driver.Navigate("https://www.amazon.co.uk/");
        }

        private static async Task<MyDriver> CreateDriverAsync()
        {
            var logContext = Log.CreateContext(LogEventLevel.Trace);
            var driver = new ChromeDriver();

            await Task.Delay(100);

            return new MyDriver(driver, logContext);
        }
    }
}

[nvborisenko]

@MJB222398, I spent couple of hours, no ideas why it is not working as expected.

I would suggest to use the following pattern:

using (Log.CreateContext(...))
  // do something

Hopefully it will work.

[MJB222398]

@nvborisenko Afraid I cannot wrap it in a using due to the structure of the application. Disposing of it myself manually is the only option.

For me at least it feels like I want to be able to attach a logging context to a driver instance. Having the logging be static via the Log class is really confusing for me as I have many drivers created in parallel and I don't want these logs tied together. So I think I'd like to be able to set a logging context on a driver by some method IWebDriver.AddLoggingContext(ILogContext context). This logging context would then only log things this driver does. I would then disable any other default logging and use this in my case.

[YevgeniyShunevych]

Basically, the way how LogContext as an ambient context behaves in current situation is correct in term of .NET. We need to understand how ExecutionContext, async methods and AsyncLocal<T> (used under the hood in log related classes) work.

In our example Test2 method is executed in, let's say, "ExecutionContext1". Inside it calls CreateDriverAsync. The CreateDriverAsync method starts execution using the same context, but before execution it stores the state of the current ExecutionContext, executes method body, and then restores the stored ExecutionContext. So Test2 method continues its execution with absolutely the same "ExecutionContext1" context, without possible changes done inside CreateDriverAsync. When we add something to ExecutionContext inside CreateDriverAsync (basically what Log.CreateContext does) "ExecutionContext1" copy is created and the new value added to it, let's name it "ExecutionContext2". Further in scope of CreateDriverAsync method when you call other sync or async methods, they are all executed with "ExecutionContext2", so logging works there. But on the exit of CreateDriverAsync method we are also exiting "ExecutionContext2" and entering "ExecutionContext1" where there are no log context. To sum up, ExecutionContext is passed to inner async method calls, but the changes done there, stay there. The changes don't transfer to the upper level but pass to lower levels. For sync methods there are no such ExecutionContext switches.

So what we can do about that. We can extract sync CreateLogContext method out of CreateDriverAsync, call it before CreateDriverAsync and pass result to CreateDriverAsync.

[Test]
public async Task Test2()
{
    var logContext = CreateLogContext();
    using var driver = await CreateDriverAsync(logContext);

    driver.Navigate("...");
}

private ILogContext CreateLogContext() =>
    Log.CreateContext(LogEventLevel.Trace);

But I would go further. I would use NUnit's SetUp functionality which is a good place for driver creation and similar initialization things.

private ILogContext _logContext;

private MyDriver _driver;

[SetUp]
public void SetUpLogContext() =>
    _logContext = CreateLogContext();

[SetUp]
public async Task SetUpDriver() =>
    _driver = await CreateDriverAsync(_logContext);

[TearDown]
public void TearDownDriver() =>
    _driver?.Dispose();

private ILogContext CreateLogContext() =>
    Log.CreateContext(LogEventLevel.Trace);

[Test]
public async Task Test2()
{
    _driver.Navigate("...");
    //...
}

The trick is that SetUpLogContext is sync method, called first, and then async SetUpDriver is called. And it works well.

[MJB222398]

@YevgeniyShunevych Is that behaviour of NUnit's documented? As I understood it they provide zero guarantee about the order in which those two setup methods would be called. No guarantees it will be consistent for a given version and no guarantees that it will not change in the future. Anyway, due to the complexity of my solution creating the log context in a setup method like that is not ideal. But I can make it work with your first suggestion I think.

So is it the case that there is nothing to do here on the Selenium side? No fixes/changes/documentation?

[YevgeniyShunevych]

Right, there is no guarantee in order of SetUp methods. It just works this way at the moment. It's up to you whether to rely on this option.

Although it is possible to define multiple SetUp methods in the same class, you should rarely do so. Unlike methods defined in separate classes in the inheritance hierarchy, the order in which they are executed is not guaranteed.

From https://docs.nunit.org/articles/nunit/writing-tests/attributes/setup.html

[nvborisenko]

Moreover, NUnit has different execution contexts for [OneTimeSetup] and [Test], so no way to initiate LogContext one time and share it across tests.

Historical note: static Log class is considered as a primary logging mechanism to be aligned with all bindings (java, ruby and etc). It is not ideal and is not right approach from my point of view, but it is as is, at least it satisfies most of users. Applying other approaches like injecting ILogger via class constructor/property would require a big effort, including approach when each class would have OnLogMessage event. Thus LogContext approach is a negotiation between static Logger and Per-Instance Logger.

[MJB222398]

Just wanted to enquire for an update on this. Are there any plans to make improvements to the Driver logging to get this working in async contexts?

[nvborisenko]

We should fix #13839 as fundamental, and then can look at this issue.