diff --git a/dotnet/src/webdriver/DriverService.cs b/dotnet/src/webdriver/DriverService.cs index 930cd7948b705..b474b80599978 100644 --- a/dotnet/src/webdriver/DriverService.cs +++ b/dotnet/src/webdriver/DriverService.cs @@ -27,6 +27,8 @@ using System.Net.Http; using System.Threading.Tasks; using OpenQA.Selenium.Internal.Logging; +using System.Threading; +using OpenQA.Selenium.Internal; namespace OpenQA.Selenium; @@ -170,40 +172,47 @@ public int ProcessId /// protected virtual bool HasShutdown => true; + static TaskFactory _tf = new TaskFactory(); + /// /// Gets a value indicating whether the service is responding to HTTP requests. /// - protected virtual bool IsInitialized + protected virtual async Task IsInitialized() { - get - { - bool isInitialized = false; + bool isInitialized = false; - try + try + { + using (var httpClient = new HttpClient()) { - using (var httpClient = new HttpClient()) + //httpClient.DefaultRequestHeaders.ConnectionClose = true; + //httpClient.Timeout = TimeSpan.FromSeconds(2); + + Uri serviceHealthUri = new Uri(this.ServiceUrl, new Uri(DriverCommand.Status, UriKind.Relative)); + + _logger.Debug($"Probing HTTP: {serviceHealthUri}"); + + _logger.Debug("Sending GET"); + + using (var response = await httpClient.GetAsync(serviceHealthUri).ConfigureAwait(false)) { - httpClient.DefaultRequestHeaders.ConnectionClose = true; - httpClient.Timeout = TimeSpan.FromSeconds(5); + // Checking the response from the 'status' end point. Note that we are simply checking + // that the HTTP status returned is a 200 status, and that the response has the correct + // Content-Type header. A more sophisticated check would parse the JSON response and + // validate its values. At the moment we do not do this more sophisticated check. + isInitialized = response.StatusCode == HttpStatusCode.OK && response.Content.Headers.ContentType is { MediaType: string mediaType } && mediaType.StartsWith("application/json", StringComparison.OrdinalIgnoreCase); - Uri serviceHealthUri = new Uri(this.ServiceUrl, new Uri(DriverCommand.Status, UriKind.Relative)); - using (var response = Task.Run(async () => await httpClient.GetAsync(serviceHealthUri)).GetAwaiter().GetResult()) - { - // Checking the response from the 'status' end point. Note that we are simply checking - // that the HTTP status returned is a 200 status, and that the response has the correct - // Content-Type header. A more sophisticated check would parse the JSON response and - // validate its values. At the moment we do not do this more sophisticated check. - isInitialized = response.StatusCode == HttpStatusCode.OK && response.Content.Headers.ContentType is { MediaType: string mediaType } && mediaType.StartsWith("application/json", StringComparison.OrdinalIgnoreCase); - } + _logger.Debug($"Probed HTTP: {isInitialized}"); } } - catch (Exception ex) when (ex is HttpRequestException || ex is TaskCanceledException) - { - // Do nothing. The exception is expected, meaning driver service is not initialized. - } - - return isInitialized; } + catch (Exception ex) when (ex is HttpRequestException || ex is TaskCanceledException) + { + _logger.Warn($"Probing failed: {ex}"); + // Do nothing. The exception is expected, meaning driver service is not initialized. + } + + return isInitialized; } /// @@ -215,11 +224,15 @@ public void Dispose() GC.SuppressFinalize(this); } + // Replaced Task-based readers with dedicated threads + private Thread? _outputThread; + private Thread? _errorThread; + /// /// Starts the DriverService if it is not already running. /// [MemberNotNull(nameof(driverServiceProcess))] - public void Start() + public async Task Start() { if (this.driverServiceProcess != null) { @@ -249,18 +262,96 @@ public void Start() this.driverServiceProcess.StartInfo.RedirectStandardOutput = true; this.driverServiceProcess.StartInfo.RedirectStandardError = true; - this.driverServiceProcess.OutputDataReceived += this.OnDriverProcessDataReceived; - this.driverServiceProcess.ErrorDataReceived += this.OnDriverProcessDataReceived; + //this.driverServiceProcess.OutputDataReceived += this.OnDriverProcessDataReceived; + //this.driverServiceProcess.ErrorDataReceived += this.OnDriverProcessDataReceived; DriverProcessStartingEventArgs eventArgs = new DriverProcessStartingEventArgs(this.driverServiceProcess.StartInfo); this.OnDriverProcessStarting(eventArgs); + if (_logger.IsEnabled(LogEventLevel.Debug)) + { + _logger.Debug("Starting driver service process"); + } + // Important: Start the process and immediately begin reading the output and error streams to avoid IO deadlocks. this.driverServiceProcess.Start(); - this.driverServiceProcess.BeginOutputReadLine(); - this.driverServiceProcess.BeginErrorReadLine(); + //this.driverServiceProcess.BeginOutputReadLine(); + //this.driverServiceProcess.BeginErrorReadLine(); + + if (_logger.IsEnabled(LogEventLevel.Trace)) + { + // Capture a stable reference to the process to avoid races with Stop() nulling the field + var proc = this.driverServiceProcess; - bool serviceAvailable = this.WaitForServiceInitialization(); + _outputThread = new Thread(() => + { + try + { + if (proc == null) + { + return; + } + + using (var reader = proc.StandardOutput) + { + string? line; + while ((line = reader.ReadLine()) != null) + { + OnDriverProcessDataReceived(line); + } + } + } + catch (ObjectDisposedException) + { + // Process or stream disposed during shutdown; ignore + } + catch (IOException) + { + // Stream closed; ignore + } + }) + { + IsBackground = true, + Name = "DriverService-stdout" + }; + + _errorThread = new Thread(() => + { + try + { + if (proc == null) + { + return; + } + + using (var reader = proc.StandardError) + { + string? line; + while ((line = reader.ReadLine()) != null) + { + OnDriverProcessDataReceived(line); + } + } + } + catch (ObjectDisposedException) + { + // Process or stream disposed during shutdown; ignore + } + catch (IOException) + { + // Stream closed; ignore + } + }) + { + IsBackground = true, + Name = "DriverService-stderr" + }; + + _outputThread.Start(); + _errorThread.Start(); + } + + bool serviceAvailable = await this.WaitForServiceInitialization().ConfigureAwait(false); DriverProcessStartedEventArgs processStartedEventArgs = new DriverProcessStartedEventArgs(this.driverServiceProcess); this.OnDriverProcessStarted(processStartedEventArgs); @@ -269,6 +360,11 @@ public void Start() { throw new WebDriverException($"Cannot start the driver service on {this.ServiceUrl}"); } + + if (_logger.IsEnabled(LogEventLevel.Debug)) + { + _logger.Debug("Driver service process is started"); + } } /// @@ -291,8 +387,8 @@ protected virtual void Dispose(bool disposing) if (this.driverServiceProcess is not null) { - this.driverServiceProcess.OutputDataReceived -= this.OnDriverProcessDataReceived; - this.driverServiceProcess.ErrorDataReceived -= this.OnDriverProcessDataReceived; + //this.driverServiceProcess.OutputDataReceived -= this.OnDriverProcessDataReceived; + //this.driverServiceProcess.ErrorDataReceived -= this.OnDriverProcessDataReceived; } } @@ -333,14 +429,14 @@ protected virtual void OnDriverProcessStarted(DriverProcessStartedEventArgs even /// /// The sender of the event. /// The data received event arguments. - protected virtual void OnDriverProcessDataReceived(object sender, DataReceivedEventArgs args) + protected virtual void OnDriverProcessDataReceived(string? data) { - if (string.IsNullOrEmpty(args.Data)) + if (string.IsNullOrEmpty(data)) return; if (_logger.IsEnabled(LogEventLevel.Trace)) { - _logger.Trace(args.Data); + _logger.Trace(data); } } @@ -368,7 +464,7 @@ private void Stop() // we'll retry. We wait for exit here, since catching the exception // for a failed HTTP request due to a closed socket is particularly // expensive. - using (var response = Task.Run(async () => await httpClient.GetAsync(shutdownUrl)).GetAwaiter().GetResult()) + using (var response = Task.Run(async () => await httpClient.GetAsync(shutdownUrl).ConfigureAwait(false)).GetAwaiter().GetResult()) { } @@ -394,8 +490,17 @@ private void Stop() } } + // Wait for output/error reader threads to finish to avoid IO deadlocks + _outputThread?.Join(); + _errorThread?.Join(); + this.driverServiceProcess.Dispose(); this.driverServiceProcess = null; + + if (_logger.IsEnabled(LogEventLevel.Debug)) + { + _logger.Debug("Driver service is stopped"); + } } } @@ -405,19 +510,32 @@ private void Stop() /// /// if the service is properly started and receiving HTTP requests; /// otherwise; . - private bool WaitForServiceInitialization() + private async Task WaitForServiceInitialization() { + if (_logger.IsEnabled(LogEventLevel.Debug)) + { + _logger.Debug("Waiting until driver service is initialized"); + } + + var sw = Stopwatch.StartNew(); + bool isInitialized = false; DateTime timeout = DateTime.Now.Add(this.InitializationTimeout); while (!isInitialized && DateTime.Now < timeout) { + _logger.Debug("LOOP"); // If the driver service process has exited, we can exit early. - if (!this.IsRunning) - { - break; - } + //if (!this.IsRunning) + //{ + // break; + //} + + isInitialized = await this.IsInitialized().ConfigureAwait(false); + } - isInitialized = this.IsInitialized; + if (_logger.IsEnabled(LogEventLevel.Debug)) + { + _logger.Debug($"Driver service initialization status: {isInitialized} {sw.Elapsed}"); } return isInitialized; diff --git a/dotnet/src/webdriver/Firefox/FirefoxDriverService.cs b/dotnet/src/webdriver/Firefox/FirefoxDriverService.cs index e00c5c5ce3664..3114548b9685b 100644 --- a/dotnet/src/webdriver/Firefox/FirefoxDriverService.cs +++ b/dotnet/src/webdriver/Firefox/FirefoxDriverService.cs @@ -250,21 +250,21 @@ protected override void OnDriverProcessStarting(DriverProcessStartingEventArgs e /// /// The sender of the event. /// The data received event arguments. - protected override void OnDriverProcessDataReceived(object sender, DataReceivedEventArgs args) + protected override void OnDriverProcessDataReceived(string? data) { - if (string.IsNullOrEmpty(args.Data)) + if (string.IsNullOrEmpty(data)) return; if (!string.IsNullOrEmpty(this.LogPath)) { if (logWriter != null) { - logWriter.WriteLine(args.Data); + logWriter.WriteLine(data); } } else { - base.OnDriverProcessDataReceived(sender, args); + base.OnDriverProcessDataReceived(data); } } diff --git a/dotnet/src/webdriver/Remote/DriverServiceCommandExecutor.cs b/dotnet/src/webdriver/Remote/DriverServiceCommandExecutor.cs index 095c69cb99ab3..bee40583ae2b9 100644 --- a/dotnet/src/webdriver/Remote/DriverServiceCommandExecutor.cs +++ b/dotnet/src/webdriver/Remote/DriverServiceCommandExecutor.cs @@ -115,7 +115,7 @@ public async Task ExecuteAsync(Command commandToExecute) Response toReturn; if (commandToExecute.Name == DriverCommand.NewSession) { - this.service.Start(); + await this.service.Start().ConfigureAwait(false); } // Use a try-catch block to catch exceptions for the Quit diff --git a/dotnet/src/webdriver/Remote/ICommandServer.cs b/dotnet/src/webdriver/Remote/ICommandServer.cs index b76731de57a73..b42515d9f576d 100644 --- a/dotnet/src/webdriver/Remote/ICommandServer.cs +++ b/dotnet/src/webdriver/Remote/ICommandServer.cs @@ -18,6 +18,7 @@ // using System; +using System.Threading.Tasks; namespace OpenQA.Selenium.Remote; @@ -29,5 +30,5 @@ public interface ICommandServer : IDisposable /// /// Starts the server. /// - void Start(); + Task Start(); }