[xharness] Improve logging.

Make sure as much as possible is written to the logs, and not stdout.

Also copy an extra 1024 bytes when fetching the system log (and continue
capturing a while after stopped, since there may be unflushed system log
data in memory).

tests/xharness/AppRunner.cs

@@ -361,7 +361,8 @@ namespace xharness
 				throw new NotImplementedException ();
 			}
 			listener_log = Logs.CreateStream (LogDirectory, string.Format ("test-{0:yyyyMMdd_HHmmss}.log", DateTime.Now), "Test log");
-			listener.Log = listener_log;
+			listener.TestLog = listener_log;
+			listener.Log = main_log;
 			listener.AutoExit = true;
 			listener.Address = System.Net.IPAddress.Any;
 			listener.Initialize ();

tests/xharness/Jenkins.cs

@@ -238,6 +238,8 @@ namespace xharness
 			try {
 				Directory.CreateDirectory (LogDirectory);
 				Harness.HarnessLog = MainLog = Logs.CreateStream (LogDirectory, "Harness.log", "Harness log");
+				Harness.HarnessLog.Timestamp = true;
+
 				Task.Run (async () =>
 				{
 					await PopulateTasksAsync ();
@@ -416,6 +418,7 @@ function toggleContainerVisibility (containerName)
 							var logs = test.AggregatedLogs;
 							if (logs.Count () > 0) {
 								foreach (var log in logs) {
+									log.Flush ();
 									writer.WriteLine ("<a href='{0}' type='text/plain'>{1}</a><br />", log.FullPath.Substring (LogDirectory.Length + 1), log.Description);
 									if (log.Description == "Test log") {
 										var summary = string.Empty;

tests/xharness/Log.cs

@@ -8,6 +8,7 @@ namespace xharness
 	public abstract class Log : IDisposable
 	{
 		public string Description;
+		public bool Timestamp;
 
 		protected Log ()
 		{
@@ -20,7 +21,7 @@ namespace xharness
 
 		public abstract string FullPath { get; }
 
-		protected abstract void Write (string value);
+		protected abstract void WriteImpl (string value);
 
 		public virtual StreamReader GetReader ()
 		{
@@ -32,6 +33,13 @@ namespace xharness
 			throw new NotSupportedException ();
 		}
 
+		public void Write (string value)
+		{
+			if (Timestamp)
+				value = DateTime.Now.ToString ("HH:mm:ss.fffffff") + " " + value;
+			WriteImpl (value);
+		}
+
 		public void WriteLine (string value)
 		{
 			Write (value + "\n");
@@ -47,6 +55,10 @@ namespace xharness
 			return Description;
 		}
 
+		public virtual void Flush ()
+		{
+		}
+
 #region IDisposable Support
 		protected virtual void Dispose (bool disposing)
 		{
@@ -70,7 +82,7 @@ namespace xharness
 			Path = path;
 		}
 
-		protected override void Write (string value)
+		protected override void WriteImpl (string value)
 		{
 			lock (this) {
 				using (var str = new FileStream (Path, FileMode.Append, FileAccess.Write, FileShare.Read)) {
@@ -139,7 +151,7 @@ namespace xharness
 			fs = new FileStream (path, FileMode.Create, FileAccess.Write, FileShare.Read);
 		}
 
-		protected override void Write (string value)
+		protected override void WriteImpl (string value)
 		{
 			var w = GetWriter ();
 			w.Write (value);
@@ -188,7 +200,7 @@ namespace xharness
 
 	public class ConsoleLog : Log
 	{
-		protected override void Write (string value)
+		protected override void WriteImpl (string value)
 		{
 			Console.Write (value);
 		}
@@ -210,7 +222,8 @@ namespace xharness
 		public string CapturePath { get; private set; }
 		public string Path { get; set; }
 
-		long startLength;
+		long startPosition;
+		long endPosition;
 
 		public CaptureLog (string capture_path)
 		{
@@ -220,30 +233,65 @@ namespace xharness
 		public void StartCapture ()
 		{
 			if (File.Exists (CapturePath))
-				startLength = new FileInfo (CapturePath).Length;
+				startPosition = new FileInfo (CapturePath).Length;
 		}
 
 		public void StopCapture ()
 		{
-			var endLength = new FileInfo (CapturePath).Length;
-			var length = (int) (endLength - startLength);
+			endPosition = new FileInfo (CapturePath).Length;
+
+			Capture ();
+		}
+
+		void Capture ()
+		{
+			if (startPosition == 0)
+				return;
+			
+			var currentEndPosition = endPosition;
+			if (currentEndPosition == 0)
+				currentEndPosition = new FileInfo (CapturePath).Length;
+			
+			var length = (int) (currentEndPosition - startPosition);
+			var currentLength = new FileInfo (CapturePath).Length;
+			var capturedLength = 0L;
+
+			if (File.Exists (Path))
+				capturedLength = new FileInfo (Path).Length;
+
+			// capture 1k more data than when we stopped, since the system log
+			// is cached in memory and flushed once in a while (so when the app
+			// requests the system log to be captured, it's usually not complete).
+			var availableLength = currentLength - startPosition;
+			if (availableLength <= capturedLength)
+				return; // We've captured before, and nothing new as added since last time.
+
+			// Capture at most 1k more
+			availableLength = Math.Min (availableLength, length + 1024);
 
 			using (var reader = new FileStream (CapturePath, FileMode.Open, FileAccess.Read, FileShare.ReadWrite)) {
 				using (var writer = new FileStream (Path, FileMode.Create, FileAccess.Write, FileShare.Read)) {
 					var buffer = new byte [4096];
-					reader.Position = startLength;
-					while (length > 0) {
+					reader.Position = startPosition;
+					while (availableLength > 0) {
 						int read = reader.Read (buffer, 0, Math.Min (buffer.Length, length));
 						if (read > 0) {
 							writer.Write (buffer, 0, read);
-							length -= read;
+							availableLength -= read;
 						}
 					}
 				}
 			}
 		}
 
-		protected override void Write (string value)
+		public override void Flush ()
+		{
+			base.Flush ();
+
+			Capture ();
+		}
+
+		protected override void WriteImpl (string value)
 		{
 			throw new InvalidOperationException ();
 		}

tests/xharness/Process_Extensions.cs

@@ -135,12 +135,12 @@ namespace xharness
 			process.BeginErrorReadLine ();
 			process.BeginOutputReadLine ();
 
-			if (cancellation_token.HasValue) {
-				cancellation_token.Value.Register (() => {
-					if (exit_completion.TrySetCanceled ())
-						ProcessHelper.kill (process.Id, 9);
-				});
-			}
+			cancellation_token?.Register (() => {
+				if (!exit_completion.Task.IsCompleted) {
+					StderrStream.WriteLine ($"Execution was cancelled.");
+					ProcessHelper.kill (process.Id, 9);
+				}
+			});
 
 			new Thread (() =>
 			{

tests/xharness/SimpleHttpListener.cs

@@ -29,7 +29,7 @@ namespace xharness
 					Port = newPort;
 					break;
 				} catch (Exception ex) {
-					Console.WriteLine ("Failed to listen on port {0}: {1}", newPort, ex.Message);
+					Log.WriteLine ("Failed to listen on port {0}: {1}", newPort, ex.Message);
 				}
 			}
 		}
@@ -44,7 +44,7 @@ namespace xharness
 			bool processed;
 
 			try {
-				Console.WriteLine ("Test log server listening on: {0}:{1}", Address, Port);
+				Log.WriteLine ("Test log server listening on: {0}:{1}", Address, Port);
 				do {
 					var context = server.GetContext ();
 					processed = Processing (context);
@@ -87,7 +87,7 @@ namespace xharness
 				finished = true;
 				break;
 			default:
-				Console.WriteLine ("Unknown upload url: {0}", request.RawUrl);
+				Log.WriteLine ("Unknown upload url: {0}", request.RawUrl);
 				response = $"Unknown upload url: {request.RawUrl}";
 				break;
 			}

tests/xharness/SimpleListener.cs

@@ -15,7 +15,8 @@ namespace xharness
 
 		public IPAddress Address { get; set; }
 		public int Port { get; set; }
-		public LogStream Log { get; set; }
+		public Log Log { get; set; }
+		public LogStream TestLog { get; set; }
 		public bool AutoExit { get; set; }
 
 		public abstract void Initialize ();
@@ -30,7 +31,7 @@ namespace xharness
 
 		protected void Connected (string remote)
 		{
-			Console.WriteLine ("Connection from {0} saving logs to {1}", remote, Log.FullPath);
+			Log.WriteLine ("Connection from {0} saving logs to {1}", remote, TestLog.FullPath);
 			connected.Set ();
 
 			if (output_stream != null) {
@@ -38,7 +39,7 @@ namespace xharness
 				output_stream.Dispose ();
 			}
 
-			var fs = Log.FileStream;
+			var fs = TestLog.FileStream;
 			// a few extra bits of data only available from this side
 			string header = String.Format ("[Local Date/Time:\t{1}]{0}[Remote Address:\t{2}]{0}",
 				Environment.NewLine, DateTime.Now, remote);

tests/xharness/SimpleTcpListener.cs

@@ -32,7 +32,7 @@ namespace xharness
 
 			try {
 				do {
-					Console.WriteLine ("Test log server listening on: {0}:{1}", Address, Port);
+					Log.WriteLine ("Test log server listening on: {0}:{1}", Address, Port);
 					using (TcpClient client = server.AcceptTcpClient ()) {
 						processed = Processing (client);
 					}