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);