diff --git a/src/Microsoft.DotNet.XHarness.Apple/AppTester.cs b/src/Microsoft.DotNet.XHarness.Apple/AppTester.cs index e9e35a12519d1..01d92fa8880d3 100644 --- a/src/Microsoft.DotNet.XHarness.Apple/AppTester.cs +++ b/src/Microsoft.DotNet.XHarness.Apple/AppTester.cs @@ -126,7 +126,7 @@ public AppTester( var runMode = target.Platform.ToRunMode(); var isSimulator = target.Platform.IsSimulator(); - var deviceListenerLog = _logs.Create($"test-{target.AsString()}-{_helpers.Timestamp}.log", LogType.TestLog.ToString(), timestamp: true); + var deviceListenerLog = _logs.Create($"test-{target.AsString()}-{_helpers.Timestamp}.log", LogType.TestLog.ToString(), timestamp: false); var (deviceListenerTransport, deviceListener, deviceListenerTmpFile) = _listenerFactory.Create( runMode, @@ -294,6 +294,8 @@ private async Task RunDeviceTests( CancellationToken cancellationToken) { var deviceSystemLog = _logs.Create($"device-{device.Name}-{_helpers.Timestamp}.log", LogType.SystemLog.ToString()); + deviceSystemLog.Timestamp = false; + var deviceLogCapturer = _deviceLogCapturerFactory.Create(_mainLog, deviceSystemLog, device.Name); deviceLogCapturer.StartCapture(); @@ -311,7 +313,7 @@ private async Task RunDeviceTests( await tunnel.Started; } - _mainLog.WriteLine("Starting test run"); + _mainLog.WriteLine("Starting the application"); var envVars = new Dictionary(); AddExtraEnvVars(envVars, extraEnvVariables); @@ -342,7 +344,7 @@ private async Task RunDeviceTests( // Upload the system log if (File.Exists(deviceSystemLog.FullPath)) { - _mainLog.WriteLine("A capture of the device log is: {0}", deviceSystemLog.FullPath); + _mainLog.WriteLine("Device log captured in {0}", deviceSystemLog.FullPath); } } diff --git a/src/Microsoft.DotNet.XHarness.CLI/Commands/Apple/AppleAppCommand.cs b/src/Microsoft.DotNet.XHarness.CLI/Commands/Apple/AppleAppCommand.cs index 85b6cf856fd7d..91ec83640c6e1 100644 --- a/src/Microsoft.DotNet.XHarness.CLI/Commands/Apple/AppleAppCommand.cs +++ b/src/Microsoft.DotNet.XHarness.CLI/Commands/Apple/AppleAppCommand.cs @@ -51,10 +51,12 @@ protected sealed override async Task InvokeInternal(Extensions.Logging // Create main log file for the run string logFileName = $"{Name}-{target.AsString()}{(AppleAppArguments.DeviceName != null ? "-" + AppleAppArguments.DeviceName : null)}.log"; + IFileBackedLog mainLog = logs.Create(logFileName, LogType.ExecutionLog.ToString(), timestamp: true); - IFileBackedLog mainLog = Log.CreateReadableAggregatedLog( - logs.Create(logFileName, LogType.ExecutionLog.ToString(), true), - new CallbackLog(message => logger.LogDebug(message.Trim())) { Timestamp = false }); + // Pipe the execution log to the debug output of XHarness effectively making "-v" turn this on + CallbackLog debugLog = new(message => logger.LogDebug(message.Trim())); + mainLog = Log.CreateReadableAggregatedLog(mainLog, debugLog); + mainLog.Timestamp = true; var exitCodeForRun = await InvokeInternal(processManager, appBundleInformationParser, deviceFinder, logger, target, logs, mainLog, cts.Token); if (exitCodeForRun != ExitCode.SUCCESS) diff --git a/src/Microsoft.DotNet.XHarness.CLI/Commands/WASM/JS/WasmTestCommand.cs b/src/Microsoft.DotNet.XHarness.CLI/Commands/WASM/JS/WasmTestCommand.cs index e4014b45cb9ca..c849789f56cc2 100644 --- a/src/Microsoft.DotNet.XHarness.CLI/Commands/WASM/JS/WasmTestCommand.cs +++ b/src/Microsoft.DotNet.XHarness.CLI/Commands/WASM/JS/WasmTestCommand.cs @@ -99,7 +99,7 @@ protected override async Task InvokeInternal(ILogger logger) engineBinary, engineArgs, log: new CallbackLog(m => logger.LogInformation(m)), - stdoutLog: new CallbackLog(logProcessor.Invoke) { Timestamp = false /* we need the plain XML string so disable timestamp */ }, + stdoutLog: new CallbackLog(logProcessor.Invoke), stderrLog: new CallbackLog(m => logger.LogError(m)), _arguments.Timeout); if (result.ExitCode != _arguments.ExpectedExitCode) diff --git a/src/Microsoft.DotNet.XHarness.Common/Logging/AggregatedLog.cs b/src/Microsoft.DotNet.XHarness.Common/Logging/AggregatedLog.cs index 9be25c2b3a997..2db8b82867100 100644 --- a/src/Microsoft.DotNet.XHarness.Common/Logging/AggregatedLog.cs +++ b/src/Microsoft.DotNet.XHarness.Common/Logging/AggregatedLog.cs @@ -23,6 +23,7 @@ private class AggregatedLog : Log public AggregatedLog(params ILog[] logs) { _logs.AddRange(logs); + Timestamp = false; } protected override void WriteImpl(string value) @@ -67,6 +68,7 @@ public ReadableAggregatedLog(IFileBackedLog defaultLog, params ILog[] logs) : ba _defaultLog = defaultLog ?? throw new ArgumentNullException(nameof(defaultLog)); // make sure that we also write in the default log _logs.Add(defaultLog); + Timestamp = false; } public StreamReader GetReader() => _defaultLog.GetReader(); diff --git a/src/Microsoft.DotNet.XHarness.Common/Logging/CallbackLog.cs b/src/Microsoft.DotNet.XHarness.Common/Logging/CallbackLog.cs index 2df1ae79c6f30..0f8a8bcd0b2f6 100644 --- a/src/Microsoft.DotNet.XHarness.Common/Logging/CallbackLog.cs +++ b/src/Microsoft.DotNet.XHarness.Common/Logging/CallbackLog.cs @@ -19,6 +19,7 @@ public CallbackLog(Action onWrite) : base("Callback log") { _onWrite = onWrite; + Timestamp = false; } public override void Dispose() diff --git a/src/Microsoft.DotNet.XHarness.TestRunners.Common/ApplicationOptions.cs b/src/Microsoft.DotNet.XHarness.TestRunners.Common/ApplicationOptions.cs index 75bbead9a4ca8..8d74960681435 100644 --- a/src/Microsoft.DotNet.XHarness.TestRunners.Common/ApplicationOptions.cs +++ b/src/Microsoft.DotNet.XHarness.TestRunners.Common/ApplicationOptions.cs @@ -49,6 +49,11 @@ public ApplicationOptions() EnableXml = b; } + if (bool.TryParse(Environment.GetEnvironmentVariable(EnviromentVariables.UseTcpTunnel), out b)) + { + UseTunnel = b; + } + var xml_version = Environment.GetEnvironmentVariable(EnviromentVariables.XmlVersion); if (!string.IsNullOrEmpty(xml_version)) { @@ -76,6 +81,7 @@ public ApplicationOptions() { "autostart", "If the app should automatically start running the tests", v => AutoStart = true }, { "hostname=", "Comma-separated list of host names or IP address to (try to) connect to", v => HostName = v }, { "hostport=", "HTTP/TCP port to connect to", v => HostPort = int.Parse (v) }, + { "tcp-tunnel", "Use a TCP tunnel for communication between the app and XHarness", v => UseTunnel = true }, { "enablexml", "Enable the xml reported", v => EnableXml = false }, { "xmlversion", "The XML format", v => XmlVersion = (XmlResultJargon) Enum.Parse (typeof (XmlResultJargon), v, false) }, { "run-all-tests:", "Run all the tests found in the assembly, defaults to true", v => @@ -128,6 +134,11 @@ public ApplicationOptions() /// public bool EnableXml { get; private set; } = true; // always true by default + /// + /// Use a TCP tunnel for communication between the app and XHarness. + /// + public bool UseTunnel { get; private set; } + /// /// The name of the host that has the device plugged. /// diff --git a/src/Microsoft.DotNet.XHarness.TestRunners.Common/TcpTextWriter.cs b/src/Microsoft.DotNet.XHarness.TestRunners.Common/TcpTextWriter.cs index fd5605cea99e3..9e1ae5cca2942 100644 --- a/src/Microsoft.DotNet.XHarness.TestRunners.Common/TcpTextWriter.cs +++ b/src/Microsoft.DotNet.XHarness.TestRunners.Common/TcpTextWriter.cs @@ -9,6 +9,7 @@ using System; using System.IO; +using System.Net; using System.Net.Sockets; using System.Text; using System.Threading; @@ -18,6 +19,7 @@ namespace Microsoft.DotNet.XHarness.TestRunners.Common internal class TcpTextWriter : TextWriter { private readonly TcpClient _client; + private readonly TcpListener _server; private readonly StreamWriter _writer; private static string SelectHostName(string[] names, int port) @@ -85,22 +87,50 @@ private static string SelectHostName(string[] names, int port) return result; } - public TcpTextWriter(string hostName, int port) + public TcpTextWriter(string hostName, int port, bool isTunnel = false) { if ((port < 0) || (port > ushort.MaxValue)) { throw new ArgumentOutOfRangeException(nameof(port), $"Port must be between 0 and {ushort.MaxValue}"); } - if (hostName == null) + if (!isTunnel && hostName == null) { throw new ArgumentNullException(nameof(hostName)); } - HostName = SelectHostName(hostName.Split(','), port); + if (!isTunnel) + { + HostName = SelectHostName(hostName.Split(','), port); + } + Port = port; - _client = new TcpClient(HostName, port); + if (isTunnel) + { + _server = new TcpListener(IPAddress.Any, Port); + _server.Server.ReceiveTimeout = 5000; + _server.Start(); + + _client = _server.AcceptTcpClient(); + + // Block until we have the ping from the client side + byte[] buffer = new byte[16 * 1024]; + var stream = _client.GetStream(); + while ((_ = stream.Read(buffer, 0, buffer.Length)) != 0) + { + var message = Encoding.UTF8.GetString(buffer); + if (message.Contains("ping")) + { + break; + } + } + } + else + { + _client = new TcpClient(HostName, port); + } + _writer = new StreamWriter(_client.GetStream()); } diff --git a/src/Microsoft.DotNet.XHarness.TestRunners.Xunit/iOSApplicationEntryPoint.cs b/src/Microsoft.DotNet.XHarness.TestRunners.Xunit/iOSApplicationEntryPoint.cs index 6245a24b06a8b..7c9adaea1ef6b 100644 --- a/src/Microsoft.DotNet.XHarness.TestRunners.Xunit/iOSApplicationEntryPoint.cs +++ b/src/Microsoft.DotNet.XHarness.TestRunners.Xunit/iOSApplicationEntryPoint.cs @@ -27,7 +27,7 @@ public override async Task RunAsync() { try { - writer = new TcpTextWriter(options.HostName, options.HostPort); + writer = new TcpTextWriter(options.HostName, options.HostPort, options.UseTunnel); } catch (Exception ex) { diff --git a/src/Microsoft.DotNet.XHarness.iOS.Shared/Listeners/SimpleTcpListener.cs b/src/Microsoft.DotNet.XHarness.iOS.Shared/Listeners/SimpleTcpListener.cs index b297e31063cdc..1b8b538113ca1 100644 --- a/src/Microsoft.DotNet.XHarness.iOS.Shared/Listeners/SimpleTcpListener.cs +++ b/src/Microsoft.DotNet.XHarness.iOS.Shared/Listeners/SimpleTcpListener.cs @@ -3,6 +3,7 @@ // See the LICENSE file in the project root for more information. using System; +using System.Diagnostics; using System.Net; using System.Net.Sockets; using System.Text; @@ -14,8 +15,10 @@ namespace Microsoft.DotNet.XHarness.iOS.Shared.Listeners { public class SimpleTcpListener : SimpleListener, ITunnelListener { - private const int TimeOutInit = 100; - private const int TimeOutIncrement = 250; + private readonly TimeSpan _retryPeriod = TimeSpan.FromMilliseconds(100); + private readonly TimeSpan _retryPeriodIncreased = TimeSpan.FromMilliseconds(250); + private readonly TimeSpan _increaseAfter = TimeSpan.FromSeconds(20); + private readonly TimeSpan _timeoutAfter = TimeSpan.FromMinutes(2); private readonly bool _autoExit; private readonly bool _useTcpTunnel = true; @@ -118,37 +121,54 @@ private void StartTcpTunnel() { // do nothing until the tunnel is ready throw new InvalidOperationException("Tcp tunnel could not be initialized."); } + bool processed; try { - int timeout = TimeOutInit; - var watch = new System.Diagnostics.Stopwatch(); - watch.Start(); + var timeout = _retryPeriod; + int logCounter = 0; + var watch = Stopwatch.StartNew(); + const string address = "localhost"; + while (true) { try { - _client = new TcpClient("localhost", Port); - Log.WriteLine("Test log server listening on: {0}:{1}", "localhost", Port); - // let the device know we are ready! + _client = new TcpClient(address, Port); + Log.WriteLine($"Test log server listening on: {address}:{Port}"); + var stream = _client.GetStream(); + + // Let the device know we are ready! var ping = Encoding.UTF8.GetBytes("ping"); stream.Write(ping, 0, ping.Length); + break; } catch (SocketException ex) { - if (timeout == TimeOutInit && watch.ElapsedMilliseconds > 20000) + // Give up after some time + if (watch.Elapsed > _timeoutAfter) { - timeout = TimeOutIncrement; // Switch to a 250ms timeout after 20 seconds + Log.WriteLine($"TCP connection hasn't started in time ({_timeoutAfter:hh\\:mm\\:ss}). Stopped listening."); + throw ex; } - else if (watch.ElapsedMilliseconds > 120000) + + // Switch to a 250 ms timeout after 20 seconds + if (timeout == _retryPeriod && watch.Elapsed > _increaseAfter) { - // Give up after 2 minutes. - throw ex; + timeout = _retryPeriodIncreased; + Log.WriteLine( + $"TCP tunnel still has not connected. " + + $"Increasing retry period from {(int)_retryPeriod.TotalMilliseconds} ms " + + $"to {(int)_retryPeriodIncreased.TotalMilliseconds} ms"); + + } else if ((++logCounter) % 100 == 0) + { + Log.WriteLine($"TCP tunnel still has not connected"); } - Log.WriteLine($"Could not connect to TCP tunnel. Retrying in {timeout} milliseconds."); + Thread.Sleep(timeout); } } @@ -163,7 +183,7 @@ private void StartTcpTunnel() { if (!(e is SocketException se) || se.SocketErrorCode != SocketError.Interrupted) { - Log.WriteLine("[{0}] : {1}", DateTime.Now, e); + Log.WriteLine($"Failed to read TCP data: {e}"); } } finally diff --git a/src/Microsoft.DotNet.XHarness.iOS.Shared/Listeners/TcpTunnel.cs b/src/Microsoft.DotNet.XHarness.iOS.Shared/Listeners/TcpTunnel.cs index c83e605ef7465..93541adbc8435 100644 --- a/src/Microsoft.DotNet.XHarness.iOS.Shared/Listeners/TcpTunnel.cs +++ b/src/Microsoft.DotNet.XHarness.iOS.Shared/Listeners/TcpTunnel.cs @@ -68,20 +68,20 @@ public void Open(string device, ITunnelListener simpleListener, TimeSpan timeout // launch app, but do not await for the result, since we need to create the tunnel var tcpArgs = new MlaunchArguments { - new TcpTunnelArgument (simpleListener.Port), - new DeviceNameArgument (device), + new TcpTunnelArgument(simpleListener.Port), + new DeviceNameArgument(device), }; // use a cancelation token, later will be used to kill the tcp tunnel process _cancellationToken = new CancellationTokenSource(); - mainLog.WriteLine($"Starting tcp tunnel between mac port: {simpleListener.Port} and devie port {simpleListener.Port}."); + mainLog.WriteLine($"Starting TCP tunnel between mac port: {simpleListener.Port} and device port {simpleListener.Port}"); Port = simpleListener.Port; var tunnelbackLog = new CallbackLog((line) => { - mainLog.WriteLine($"The tcp tunnel output is {line}"); + mainLog.WriteLine($"[TCP tunnel] {line}"); if (line.Contains("Tcp tunnel started on device")) { - mainLog.Write($"Tcp tunnel created on port {simpleListener.Port}"); + mainLog.Write($"TCP tunnel created on port {simpleListener.Port}"); startedCompletionSource.TrySetResult(true); simpleListener.TunnelHoleThrough.TrySetResult(true); }