Fix TCP tunnel (dotnet#573)

- The port wasn't opened on the device so the tunnel was never connected properly
- Fixing multiple timestamps in logs (cascades of callback/aggregated logs)
- Fixing how we log details when waiting for connections

Resolves dotnet#570

Testing showed that mlaunch doesn't quit when app is finished though (dotnet#574)

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

src/Microsoft.DotNet.XHarness.CLI/Commands/Apple/AppleAppCommand.cs

@@ -51,10 +51,12 @@ protected sealed override async Task<ExitCode> 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)

src/Microsoft.DotNet.XHarness.CLI/Commands/WASM/JS/WasmTestCommand.cs

@@ -99,7 +99,7 @@ protected override async Task<ExitCode> 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)

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

src/Microsoft.DotNet.XHarness.Common/Logging/CallbackLog.cs

@@ -19,6 +19,7 @@ public CallbackLog(Action<string> onWrite)
  : base("Callback log")
  {
  _onWrite = onWrite;
+ Timestamp = false;
  }
 
  public override void Dispose()

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()
  /// </summary>
  public bool EnableXml { get; private set; } = true; // always true by default
 
+ /// <summary>
+ /// Use a TCP tunnel for communication between the app and XHarness.
+ /// </summary>
+ public bool UseTunnel { get; private set; }
+
  /// <summary>
  /// The name of the host that has the device plugged.
  /// </summary>

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

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

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

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