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.

This commit is contained in:
Damian Büchel 2024-09-04 15:14:55 +02:00
parent d5b182ae2f
commit 9762019499
9 changed files with 131 additions and 48 deletions

View file

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

View file

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

View file

@ -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<int>(success, health, message);

View file

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

View file

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

View file

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

View file

@ -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}!");
}
}
}

View file

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

View file

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