diff --git a/SafeExamBrowser.Client/Behaviour/ClientController.cs b/SafeExamBrowser.Client/Behaviour/ClientController.cs index d4ad2a40..f8cb2804 100644 --- a/SafeExamBrowser.Client/Behaviour/ClientController.cs +++ b/SafeExamBrowser.Client/Behaviour/ClientController.cs @@ -74,6 +74,8 @@ namespace SafeExamBrowser.Client.Behaviour public bool TryStart() { + logger.Info("--- Initiating startup procedure ---"); + splashScreen = uiFactory.CreateSplashScreen(); operations.ProgressIndicator = splashScreen; @@ -86,6 +88,14 @@ namespace SafeExamBrowser.Client.Behaviour RegisterEvents(); runtime.InformClientReady(); splashScreen.Hide(); + + logger.Info("--- Application successfully initialized ---"); + logger.Log(string.Empty); + } + else + { + logger.Info("--- Application startup aborted! ---"); + logger.Log(string.Empty); } return success; @@ -93,13 +103,27 @@ namespace SafeExamBrowser.Client.Behaviour public void Terminate() { + logger.Log(string.Empty); + logger.Info("--- Initiating shutdown procedure ---"); + splashScreen.Show(); splashScreen.BringToForeground(); // TODO DeregisterEvents(); - operations.TryRevert(); + var success = operations.TryRevert(); + + if (success) + { + logger.Info("--- Application successfully finalized ---"); + logger.Log(string.Empty); + } + else + { + logger.Info("--- Shutdown procedure failed! ---"); + logger.Log(string.Empty); + } splashScreen?.Close(); } diff --git a/SafeExamBrowser.Client/CompositionRoot.cs b/SafeExamBrowser.Client/CompositionRoot.cs index ee834eeb..2e698300 100644 --- a/SafeExamBrowser.Client/CompositionRoot.cs +++ b/SafeExamBrowser.Client/CompositionRoot.cs @@ -105,7 +105,6 @@ namespace SafeExamBrowser.Client internal void LogShutdownInformation() { - logger?.Log(string.Empty); logger?.Log($"# Client instance terminated at {DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss.fff")}"); } diff --git a/SafeExamBrowser.Runtime/Behaviour/Operations/SessionSequenceOperation.cs b/SafeExamBrowser.Runtime/Behaviour/Operations/SessionSequenceOperation.cs index f29da2a1..827df9f9 100644 --- a/SafeExamBrowser.Runtime/Behaviour/Operations/SessionSequenceOperation.cs +++ b/SafeExamBrowser.Runtime/Behaviour/Operations/SessionSequenceOperation.cs @@ -62,11 +62,12 @@ namespace SafeExamBrowser.Runtime.Behaviour.Operations session = configuration.InitializeSession(); runtimeHost.StartupToken = session.StartupToken; + logger.Info("Initializing service session..."); service.StartSession(session.Id, configuration.CurrentSettings); try { - StartClient(); + sessionRunning = TryStartClient(); } catch (Exception e) { @@ -80,7 +81,7 @@ namespace SafeExamBrowser.Runtime.Behaviour.Operations else { Abort = true; - logger.Info($"Failed to start new session! Aborting..."); + logger.Info($"Failed to start new session! Reverting service session and aborting procedure..."); service.StopSession(session.Id); } } @@ -92,6 +93,7 @@ namespace SafeExamBrowser.Runtime.Behaviour.Operations logger.Info($"Stopping session with identifier '{session.Id}'..."); ProgressIndicator?.UpdateText(TextKey.ProgressIndicator_StopSession, true); + logger.Info("Stopping service session..."); service.StopSession(session.Id); try @@ -108,7 +110,7 @@ namespace SafeExamBrowser.Runtime.Behaviour.Operations } } - private void StartClient() + private bool TryStartClient() { var clientReady = false; var clientReadyEvent = new AutoResetEvent(false); @@ -118,39 +120,44 @@ namespace SafeExamBrowser.Runtime.Behaviour.Operations var hostUri = configuration.RuntimeInfo.RuntimeAddress; var token = session.StartupToken.ToString("D"); + logger.Info("Starting new client process."); runtimeHost.ClientReady += clientReadyEventHandler; - session.ClientProcess = processFactory.StartNew(clientExecutable, clientLogFile, hostUri, token); - clientReady = clientReadyEvent.WaitOne(TEN_SECONDS); + logger.Info("Waiting for client to complete initialization..."); + clientReady = clientReadyEvent.WaitOne(TEN_SECONDS); runtimeHost.ClientReady -= clientReadyEventHandler; - // TODO: Check if client process alive! - if (clientReady) - { - if (client.Connect(session.StartupToken)) - { - var response = client.RequestAuthentication(); - - // TODO: Further integrity checks necessary? - if (session.ClientProcess.Id == response?.ProcessId) - { - sessionRunning = true; - } - else - { - logger.Error("Failed to verify client integrity!"); - } - } - else - { - logger.Error("Failed to connect to client!"); - } - } - else + if (!clientReady) { logger.Error($"Failed to start client within {TEN_SECONDS / 1000} seconds!"); + + return false; } + + logger.Info("Client has been successfully started and initialized."); + + if (!client.Connect(session.StartupToken)) + { + logger.Error("Failed to connect to client!"); + + return false; + } + + logger.Info("Connection with client has been established."); + + var response = client.RequestAuthentication(); + + if (session.ClientProcess.Id != response?.ProcessId) + { + logger.Error("Failed to verify client integrity!"); + + return false; + } + + logger.Info("Authentication of client has been successful."); + + return true; } private void StopClient() @@ -166,12 +173,28 @@ namespace SafeExamBrowser.Runtime.Behaviour.Operations runtimeHost.ClientDisconnected += disconnectedEventHandler; session.ClientProcess.Terminated += terminatedEventHandler; + logger.Info("Instructing client to initiate shutdown procedure."); client.InitiateShutdown(); + + logger.Info("Disconnecting from client communication host."); client.Disconnect(); + logger.Info("Waiting for client to disconnect from runtime communication host..."); disconnected = disconnectedEvent.WaitOne(TEN_SECONDS); + + if (!disconnected) + { + logger.Error($"Client failed to disconnect within {TEN_SECONDS / 1000} seconds!"); + } + + logger.Info("Waiting for client process to terminate..."); terminated = terminatedEvent.WaitOne(TEN_SECONDS); + if (!terminated) + { + logger.Error($"Client failed to terminate within {TEN_SECONDS / 1000} seconds!"); + } + runtimeHost.ClientDisconnected -= disconnectedEventHandler; session.ClientProcess.Terminated -= terminatedEventHandler; @@ -181,15 +204,7 @@ namespace SafeExamBrowser.Runtime.Behaviour.Operations } else { - if (!disconnected) - { - logger.Error($"Client failed to disconnect within {TEN_SECONDS / 1000} seconds!"); - } - else if (!terminated) - { - logger.Error($"Client failed to terminate within {TEN_SECONDS / 1000} seconds!"); - } - + logger.Warn("Attempting to kill client process since graceful shutdown failed!"); KillClient(); } } diff --git a/SafeExamBrowser.Runtime/Behaviour/RuntimeController.cs b/SafeExamBrowser.Runtime/Behaviour/RuntimeController.cs index ac8619c4..ab3ff9a5 100644 --- a/SafeExamBrowser.Runtime/Behaviour/RuntimeController.cs +++ b/SafeExamBrowser.Runtime/Behaviour/RuntimeController.cs @@ -75,7 +75,7 @@ namespace SafeExamBrowser.Runtime.Behaviour if (initialized) { - logger.Info("--- Application successfully initialized! ---"); + logger.Info("--- Application successfully initialized ---"); logger.Log(string.Empty); logger.Subscribe(runtimeWindow); @@ -112,7 +112,7 @@ namespace SafeExamBrowser.Runtime.Behaviour if (success) { - logger.Info("--- Application successfully finalized! ---"); + logger.Info("--- Application successfully finalized ---"); logger.Log(string.Empty); } else @@ -127,11 +127,13 @@ namespace SafeExamBrowser.Runtime.Behaviour private void StartSession(bool initial = false) { runtimeWindow.Show(); + logger.Info(">------ Initiating session procedure ------<"); sessionRunning = initial ? sessionSequence.TryPerform() : sessionSequence.TryRepeat(); if (sessionRunning) { + logger.Info(">------ Session is running ------<"); runtimeWindow.HideProgressBar(); runtimeWindow.UpdateText(TextKey.RuntimeWindow_ApplicationRunning); @@ -142,6 +144,7 @@ namespace SafeExamBrowser.Runtime.Behaviour } else { + logger.Info(">------ Session procedure was aborted! ------<"); // TODO: Not when user chose to terminate after reconfiguration! Probably needs IOperationSequenceResult or alike... uiFactory.Show(TextKey.MessageBox_SessionStartError, TextKey.MessageBox_SessionStartErrorTitle, icon: MessageBoxIcon.Error); @@ -157,17 +160,21 @@ namespace SafeExamBrowser.Runtime.Behaviour runtimeWindow.Show(); runtimeWindow.BringToForeground(); runtimeWindow.ShowProgressBar(); + logger.Info(">------ Reverting session operations ------<"); var success = sessionSequence.TryRevert(); if (success) { + logger.Info(">------ Session is terminated ------<"); sessionRunning = false; // TODO } else { + logger.Info(">------ Session reversion was erroneous! ------<"); + // TODO } }