From 9762019499f70bc5fa88a8204b2b90a3e1b1df8d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Damian=20B=C3=BCchel?= Date: Wed, 4 Sep 2024 15:14:55 +0200 Subject: [PATCH] SEBWIN-936: Resolved errors and improved transmission spooler, reduced and improved logging of service and server proxies resp. requests, specified timeout for service requests and fixed missing cache path in proctoring finalization dialog. --- .../Service/Requests/Extensions.cs | 16 +++- .../Service/Requests/Request.cs | 19 ++++- .../ScreenProctoring/Service/ServiceProxy.cs | 8 +- .../ScreenProctoring/TransmissionSpooler.cs | 81 +++++++++++-------- SafeExamBrowser.Server/Extensions.cs | 16 +++- .../Requests/BaseRequest.cs | 29 ++++++- SafeExamBrowser.Server/ServerProxy.cs | 6 +- .../ProctoringFinalizationDialog.xaml.cs | 2 +- .../ProctoringFinalizationDialog.xaml.cs | 2 +- 9 files changed, 131 insertions(+), 48 deletions(-) diff --git a/SafeExamBrowser.Proctoring/ScreenProctoring/Service/Requests/Extensions.cs b/SafeExamBrowser.Proctoring/ScreenProctoring/Service/Requests/Extensions.cs index 9a42d24b..6a12b521 100644 --- a/SafeExamBrowser.Proctoring/ScreenProctoring/Service/Requests/Extensions.cs +++ b/SafeExamBrowser.Proctoring/ScreenProctoring/Service/Requests/Extensions.cs @@ -8,6 +8,7 @@ using System; using System.Net.Http; +using System.Text; namespace SafeExamBrowser.Proctoring.ScreenProctoring.Service.Requests { @@ -15,7 +16,20 @@ namespace SafeExamBrowser.Proctoring.ScreenProctoring.Service.Requests { internal static string ToLogString(this HttpResponseMessage response) { - return $"{(int?) response?.StatusCode} {response?.StatusCode} {response?.ReasonPhrase}"; + return response == default ? "No Response" : $"{(int) response.StatusCode} {response.StatusCode} {response.ReasonPhrase}"; + } + + internal static string ToSummary(this Exception exception) + { + var trimChars = new[] { '.', '!' }; + var summary = new StringBuilder(exception.Message?.TrimEnd(trimChars)); + + for (var inner = exception.InnerException; inner != default; inner = inner.InnerException) + { + summary.Append($" -> {inner.Message?.TrimEnd(trimChars)}"); + } + + return summary.ToString(); } internal static long ToUnixTimestamp(this DateTime date) diff --git a/SafeExamBrowser.Proctoring/ScreenProctoring/Service/Requests/Request.cs b/SafeExamBrowser.Proctoring/ScreenProctoring/Service/Requests/Request.cs index b3acab69..4389c07b 100644 --- a/SafeExamBrowser.Proctoring/ScreenProctoring/Service/Requests/Request.cs +++ b/SafeExamBrowser.Proctoring/ScreenProctoring/Service/Requests/Request.cs @@ -25,6 +25,8 @@ namespace SafeExamBrowser.Proctoring.ScreenProctoring.Service.Requests private readonly HttpClient httpClient; + private bool hadException; + protected readonly Api api; protected readonly ILogger logger; protected readonly Parser parser; @@ -74,12 +76,16 @@ namespace SafeExamBrowser.Proctoring.ScreenProctoring.Service.Requests } catch (TaskCanceledException) { - logger.Error($"Request {request.Method} '{request.RequestUri}' did not complete within {httpClient.Timeout}ms!"); + logger.Warn($"Request {request.Method} '{request.RequestUri}' did not complete within {httpClient.Timeout}!"); + break; } catch (Exception e) { - logger.Error($"Request {request.Method} '{request.RequestUri}' has failed!", e); + if (IsFirstException()) + { + logger.Warn($"Request {request.Method} '{request.RequestUri}' has failed: {e.ToSummary()}!"); + } } } @@ -144,6 +150,15 @@ namespace SafeExamBrowser.Proctoring.ScreenProctoring.Service.Requests return request; } + private bool IsFirstException() + { + var isFirst = !hadException; + + hadException = true; + + return isFirst; + } + private (string name, string value)[] UpdateOAuth2Token((string name, string value)[] headers) { var result = new List<(string name, string value)>(); diff --git a/SafeExamBrowser.Proctoring/ScreenProctoring/Service/ServiceProxy.cs b/SafeExamBrowser.Proctoring/ScreenProctoring/Service/ServiceProxy.cs index eab26c49..c507e9ab 100644 --- a/SafeExamBrowser.Proctoring/ScreenProctoring/Service/ServiceProxy.cs +++ b/SafeExamBrowser.Proctoring/ScreenProctoring/Service/ServiceProxy.cs @@ -35,7 +35,11 @@ namespace SafeExamBrowser.Proctoring.ScreenProctoring.Service internal ServiceResponse Connect(string clientId, string clientSecret, string serviceUrl) { - httpClient = new HttpClient { BaseAddress = new Uri(serviceUrl) }; + httpClient = new HttpClient + { + BaseAddress = new Uri(serviceUrl), + Timeout = TimeSpan.FromSeconds(10) + }; var request = new OAuth2TokenRequest(api, httpClient, logger, parser); var success = request.TryExecute(clientId, clientSecret, out var message); @@ -81,7 +85,7 @@ namespace SafeExamBrowser.Proctoring.ScreenProctoring.Service } else { - logger.Error("Failed to query health!"); + logger.Warn("Failed to query health!"); } return new ServiceResponse(success, health, message); diff --git a/SafeExamBrowser.Proctoring/ScreenProctoring/TransmissionSpooler.cs b/SafeExamBrowser.Proctoring/ScreenProctoring/TransmissionSpooler.cs index 6c31a127..7b281187 100644 --- a/SafeExamBrowser.Proctoring/ScreenProctoring/TransmissionSpooler.cs +++ b/SafeExamBrowser.Proctoring/ScreenProctoring/TransmissionSpooler.cs @@ -62,7 +62,7 @@ namespace SafeExamBrowser.Proctoring.ScreenProctoring var progress = 0; var total = previous; - while (HasRemainingWork() && service.IsConnected && (!networkIssue || recovering)) + while (HasRemainingWork() && service.IsConnected && (!networkIssue || recovering || DateTime.Now < resume)) { var remaining = buffer.Count + cache.Count; @@ -80,7 +80,7 @@ namespace SafeExamBrowser.Proctoring.ScreenProctoring updateStatus(new RemainingWorkUpdatedEventArgs { - IsWaiting = recovering, + IsWaiting = recovering || networkIssue, Next = buffer.TryPeek(out _, out var schedule, out _) ? schedule : default(DateTime?), Progress = progress, Resume = resume, @@ -121,6 +121,7 @@ namespace SafeExamBrowser.Proctoring.ScreenProctoring thread.Start(); timer.AutoReset = false; + timer.Elapsed += Timer_Elapsed; timer.Interval = FIFTEEN_SECONDS; } @@ -195,19 +196,6 @@ namespace SafeExamBrowser.Proctoring.ScreenProctoring private void ExecuteCaching() { - const int THREE_MINUTES = 180; - - if (!recovering) - { - recovering = true; - resume = DateTime.Now.AddSeconds(random.Next(0, THREE_MINUTES)); - - timer.Elapsed += Timer_Elapsed; - timer.Start(); - - logger.Warn($"Activating local caching and suspending transmission due to bad service health (value: {health}, resume: {resume:HH:mm:ss})."); - } - CacheFromBuffer(); CacheFromQueue(); } @@ -237,9 +225,7 @@ namespace SafeExamBrowser.Proctoring.ScreenProctoring else { timer.Stop(); - timer.Elapsed -= Timer_Elapsed; - - logger.Info($"Deactivating local caching and resuming transmission due to improved service health (value: {health})."); + logger.Info($"Recovery terminated, deactivating local caching and resuming transmission."); } } @@ -278,7 +264,7 @@ namespace SafeExamBrowser.Proctoring.ScreenProctoring } else { - buffer.Enqueue(metaData, DateTime.Now, screenShot); + buffer.Enqueue(metaData, CalculateSchedule(metaData), screenShot); } } } @@ -296,10 +282,18 @@ namespace SafeExamBrowser.Proctoring.ScreenProctoring var hasItem = buffer.TryPeek(out var metaData, out var schedule, out var screenShot); var ready = schedule <= DateTime.Now; - if (hasItem && ready && TryTransmit(metaData, screenShot)) + if (hasItem && ready) { buffer.Dequeue(); - screenShot.Dispose(); + + if (TryTransmit(metaData, screenShot)) + { + screenShot.Dispose(); + } + else + { + buffer.Enqueue(metaData, CalculateSchedule(metaData), screenShot); + } } } @@ -313,7 +307,7 @@ namespace SafeExamBrowser.Proctoring.ScreenProctoring } else { - buffer.Enqueue(metaData, DateTime.Now, screenShot); + buffer.Enqueue(metaData, CalculateSchedule(metaData), screenShot); } } } @@ -328,7 +322,7 @@ namespace SafeExamBrowser.Proctoring.ScreenProctoring } else { - buffer.Enqueue(metaData, DateTime.Now, screenShot); + buffer.Enqueue(metaData, CalculateSchedule(metaData), screenShot); } } } @@ -354,14 +348,11 @@ namespace SafeExamBrowser.Proctoring.ScreenProctoring if (service.IsConnected) { var response = service.Send(metaData, screenShot); + var value = response.Success ? response.Value : BAD; + health = UpdateHealth(value); networkIssue = !response.Success; success = response.Success; - - if (response.Success) - { - health = UpdateHealth(response.Value); - } } else { @@ -376,30 +367,52 @@ namespace SafeExamBrowser.Proctoring.ScreenProctoring if (service.IsConnected) { var response = service.GetHealth(); + var value = response.Success ? response.Value : BAD; + health = UpdateHealth(value); networkIssue = !response.Success; - - if (response.Success) - { - health = UpdateHealth(response.Value); - } } else { logger.Warn("Cannot query health as service is disconnected!"); } - timer.Start(); + if (!timer.Enabled) + { + timer.Start(); + } } private int UpdateHealth(int value) { + const int THREE_MINUTES = 180; + var previous = health; var current = value > BAD ? BAD : (value < GOOD ? GOOD : value); if (previous != current) { logger.Info($"Service health {(previous < current ? "deteriorated" : "improved")} from {previous} to {current}."); + + if (current == BAD) + { + recovering = false; + resume = DateTime.Now.AddSeconds(random.Next(0, THREE_MINUTES)); + + if (!timer.Enabled) + { + timer.Start(); + } + + logger.Warn($"Activating local caching and suspending transmission due to bad service health (resume: {resume:HH:mm:ss})."); + } + else if (previous == BAD) + { + recovering = true; + resume = DateTime.Now < resume ? resume : DateTime.Now.AddSeconds(random.Next(0, THREE_MINUTES)); + + logger.Info($"Starting recovery while maintaining local caching (resume: {resume:HH:mm:ss})."); + } } return current; diff --git a/SafeExamBrowser.Server/Extensions.cs b/SafeExamBrowser.Server/Extensions.cs index c37d4926..aa5f42ab 100644 --- a/SafeExamBrowser.Server/Extensions.cs +++ b/SafeExamBrowser.Server/Extensions.cs @@ -8,6 +8,7 @@ using System; using System.Net.Http; +using System.Text; using SafeExamBrowser.Settings.Logging; namespace SafeExamBrowser.Server @@ -16,7 +17,7 @@ namespace SafeExamBrowser.Server { internal static string ToLogString(this HttpResponseMessage response) { - return $"{(int?) response?.StatusCode} {response?.StatusCode} {response?.ReasonPhrase}"; + return response == default ? "No Response" : $"{(int) response.StatusCode} {response.StatusCode} {response.ReasonPhrase}"; } internal static string ToLogType(this LogLevel severity) @@ -36,6 +37,19 @@ namespace SafeExamBrowser.Server return "UNKNOWN"; } + internal static string ToSummary(this Exception exception) + { + var trimChars = new[] { '.', '!' }; + var summary = new StringBuilder(exception.Message?.TrimEnd(trimChars)); + + for (var inner = exception.InnerException; inner != default; inner = inner.InnerException) + { + summary.Append($" -> {inner.Message?.TrimEnd(trimChars)}"); + } + + return summary.ToString(); + } + internal static long ToUnixTimestamp(this DateTime date) { return new DateTimeOffset(date).ToUnixTimeMilliseconds(); diff --git a/SafeExamBrowser.Server/Requests/BaseRequest.cs b/SafeExamBrowser.Server/Requests/BaseRequest.cs index 0bc8d4d9..362df41a 100644 --- a/SafeExamBrowser.Server/Requests/BaseRequest.cs +++ b/SafeExamBrowser.Server/Requests/BaseRequest.cs @@ -26,6 +26,8 @@ namespace SafeExamBrowser.Server.Requests private readonly HttpClient httpClient; + private bool hadException; + protected readonly ApiVersion1 api; protected readonly ILogger logger; protected readonly Parser parser; @@ -73,7 +75,7 @@ namespace SafeExamBrowser.Server.Requests { response = httpClient.SendAsync(request).GetAwaiter().GetResult(); - if (request.RequestUri.AbsolutePath != api.LogEndpoint && request.RequestUri.AbsolutePath != api.PingEndpoint) + if (PerformLoggingFor(request)) { logger.Debug($"Completed request: {request.Method} '{request.RequestUri}' -> {response.ToLogString()}"); } @@ -90,12 +92,19 @@ namespace SafeExamBrowser.Server.Requests } catch (TaskCanceledException) { - logger.Debug($"Request {request.Method} '{request.RequestUri}' did not complete within {settings.RequestTimeout}ms!"); + if (PerformLoggingFor(request)) + { + logger.Warn($"Request {request.Method} '{request.RequestUri}' did not complete within {settings.RequestTimeout}ms!"); + } + break; } catch (Exception e) { - logger.Debug($"Request {request.Method} '{request.RequestUri}' failed due to {e}"); + if (PerformLoggingFor(request) && IsFirstException()) + { + logger.Warn($"Request {request.Method} '{request.RequestUri}' has failed: {e.ToSummary()}!"); + } } } @@ -168,6 +177,20 @@ namespace SafeExamBrowser.Server.Requests return request; } + private bool IsFirstException() + { + var isFirst = !hadException; + + hadException = true; + + return isFirst; + } + + private bool PerformLoggingFor(HttpRequestMessage request) + { + return request.RequestUri.AbsolutePath != api.LogEndpoint && request.RequestUri.AbsolutePath != api.PingEndpoint; + } + private (string name, string value)[] UpdateOAuth2Token((string name, string value)[] headers) { var result = new List<(string name, string value)>(); diff --git a/SafeExamBrowser.Server/ServerProxy.cs b/SafeExamBrowser.Server/ServerProxy.cs index 990a2df5..8f459919 100644 --- a/SafeExamBrowser.Server/ServerProxy.cs +++ b/SafeExamBrowser.Server/ServerProxy.cs @@ -418,7 +418,7 @@ namespace SafeExamBrowser.Server } else { - logger.Error($"Failed to send ping: {message}"); + logger.Warn($"Failed to send ping: {message}!"); } } catch (Exception e) @@ -449,7 +449,7 @@ namespace SafeExamBrowser.Server } else { - logger.Warn($"Failed to send power supply status! {message}"); + logger.Warn($"Failed to send power supply status: {message}!"); } } } @@ -480,7 +480,7 @@ namespace SafeExamBrowser.Server } else { - logger.Warn($"Failed to send wireless status! {message}"); + logger.Warn($"Failed to send wireless status: {message}!"); } } } diff --git a/SafeExamBrowser.UserInterface.Desktop/Windows/ProctoringFinalizationDialog.xaml.cs b/SafeExamBrowser.UserInterface.Desktop/Windows/ProctoringFinalizationDialog.xaml.cs index 5fa9b18d..a7a2ee92 100644 --- a/SafeExamBrowser.UserInterface.Desktop/Windows/ProctoringFinalizationDialog.xaml.cs +++ b/SafeExamBrowser.UserInterface.Desktop/Windows/ProctoringFinalizationDialog.xaml.cs @@ -62,7 +62,7 @@ namespace SafeExamBrowser.UserInterface.Desktop.Windows private void ShowFailure(RemainingWorkUpdatedEventArgs status) { ButtonPanel.Visibility = Visibility.Visible; - CachePath.Text = status.CachePath; + CachePath.Text = status.CachePath ?? "-"; Cursor = Cursors.Arrow; FailurePanel.Visibility = Visibility.Visible; Message.Text = text.Get(TextKey.ProctoringFinalizationDialog_FailureMessage); diff --git a/SafeExamBrowser.UserInterface.Mobile/Windows/ProctoringFinalizationDialog.xaml.cs b/SafeExamBrowser.UserInterface.Mobile/Windows/ProctoringFinalizationDialog.xaml.cs index e8a3dfbf..798f750e 100644 --- a/SafeExamBrowser.UserInterface.Mobile/Windows/ProctoringFinalizationDialog.xaml.cs +++ b/SafeExamBrowser.UserInterface.Mobile/Windows/ProctoringFinalizationDialog.xaml.cs @@ -77,7 +77,7 @@ namespace SafeExamBrowser.UserInterface.Mobile.Windows private void ShowFailure(RemainingWorkUpdatedEventArgs status) { ButtonPanel.Visibility = Visibility.Visible; - CachePath.Text = status.CachePath; + CachePath.Text = status.CachePath ?? "-"; Cursor = Cursors.Arrow; FailurePanel.Visibility = Visibility.Visible; Message.Text = text.Get(TextKey.ProctoringFinalizationDialog_FailureMessage);