SEBWIN-219: Enhanced implementation and logging of session operation.

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

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

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 (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
 			{
 				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.Warn("Attempting to kill client process since graceful shutdown failed!");
-				{
-					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!");
-				}
-
 				KillClient();
 			}
 		}

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
 			}
 		}