Skip to content

Commit

Permalink
Make compiler server logging explicit (#48557)
Browse files Browse the repository at this point in the history 
* Make compiler server logging explicit

This changes the compiler server logging infrastructure to be an
explicit resource vs. an ambient authority. This both cleans up our
implementation a bit but also allows us to take advantage of xUnit
output logging in our unit tests.

The `ITestOutputHelper` can be the implementation of an
`ICompilerServerLogger`. This means that when compiler server tests fail
we get the full benefit of our logging infrastructure in the test
output vs. having to just guess at what failed here.
  • Loading branch information
@jaredpar
jaredpar authored Nov 20, 2020
1 parent a8de425 commit 2693957
Show file tree
Hide file tree
Showing 28 changed files with 558 additions and 443 deletions.
3 changes: 2 additions & 1 deletion src/Compilers/CSharp/csc/Program.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -33,7 +33,8 @@ private static int MainCore(string[] args)
ExitingTraceListener.Install();
#endif

return BuildClient.Run(args, RequestLanguage.CSharpCompile, Csc.Run);
using var logger = new CompilerServerLogger();
return BuildClient.Run(args, RequestLanguage.CSharpCompile, Csc.Run, logger);
}

public static int Run(string[] args, string clientDir, string workingDir, string sdkDir, string tempDir, TextWriter textWriter, IAnalyzerAssemblyLoader analyzerLoader)
Expand Down
7 changes: 0 additions & 7 deletions src/Compilers/Core/CommandLine/BuildProtocol.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -80,13 +80,6 @@ public static BuildRequest Create(RequestLanguage language,
{
Debug.Assert(!string.IsNullOrWhiteSpace(compilerHash), "CompilerHash is required to send request to the build server");

Log($@"
Creating BuildRequest
Working directory: {workingDirectory}
Temp directory: {tempDirectory}
Lib directory: {libDirectory ?? null}
Compiler hash: {compilerHash}");

var requestLength = args.Count + 1 + (libDirectory == null ? 0 : 1);
var requestArgs = new List<Argument>(requestLength);

Expand Down
184 changes: 106 additions & 78 deletions src/Compilers/Core/CommandLine/CompilerServerLogger.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -8,11 +8,86 @@
using System.Diagnostics;
using System.IO;
using System.Linq;
using System.Runtime.InteropServices.WindowsRuntime;
using System.Text;
using System.Threading;

namespace Microsoft.CodeAnalysis.CommandLine
{
/// <summary>
/// Used to log information from within the compiler server
/// </summary>
/// <remarks>
/// Implementations of this interface must assume they are used on multilpe threads without any form
/// of synchronization.
/// </remarks>
internal interface ICompilerServerLogger
{
bool IsLogging { get; }
void Log(string message);
}

internal static class CompilerServerLoggerExtensions
{
internal static void Log(this ICompilerServerLogger logger, string format, params object?[] arguments)
{
if (logger.IsLogging)
{
logger.Log(string.Format(format, arguments));
}
}

internal static void LogError(this ICompilerServerLogger logger, string message)
{
if (logger.IsLogging)
{
logger.Log($"Error: {message}");
}
}

internal static void LogError(this ICompilerServerLogger logger, string format, params object?[] arguments)
{
if (logger.IsLogging)
{
logger.Log($"Error: {format}", arguments);
}
}

/// <summary>
/// Log an exception. Also logs information about inner exceptions.
/// </summary>
internal static void LogException(this ICompilerServerLogger logger, Exception exception, string reason)
{
if (!logger.IsLogging)
{
return;
}

var builder = new StringBuilder();
builder.Append("Error ");
AppendException(exception);

int innerExceptionLevel = 0;
Exception? e = exception.InnerException;
while (e != null)
{
builder.Append($"Inner exception[{innerExceptionLevel}] ");
AppendException(e);
e = e.InnerException;
innerExceptionLevel += 1;
}

logger.Log(builder.ToString());

void AppendException(Exception exception)
{
builder.AppendLine($"Error: '{exception.GetType().Name}' '{exception.Message}' occurred during '{reason}'");
builder.AppendLine("Stack trace:");
builder.AppendLine(exception.StackTrace);
}
}
}

/// <summary>
/// Class for logging information about what happens in the server and client parts of the
/// Roslyn command line compiler and build tasks. Useful for debugging what is going on.
Expand All @@ -21,130 +96,83 @@ namespace Microsoft.CodeAnalysis.CommandLine
/// To use the logging, set the environment variable RoslynCommandLineLogFile to the name
/// of a file to log to. This file is logged to by both client and server components.
/// </remarks>
internal class CompilerServerLogger
internal sealed class CompilerServerLogger : ICompilerServerLogger, IDisposable
{
// Environment variable, if set, to enable logging and set the file to log to.
private const string environmentVariable = "RoslynCommandLineLogFile";
internal const string EnvironmentVariableName = "RoslynCommandLineLogFile";
internal const string LoggingPrefix = "---";

private static readonly Stream? s_loggingStream;
private static string s_prefix = "---";
private Stream? _loggingStream;
private readonly int _processId;

public bool IsLogging => _loggingStream is object;

/// <summary>
/// Static class initializer that initializes logging.
/// </summary>
static CompilerServerLogger()
public CompilerServerLogger()
{
s_loggingStream = null;
_processId = Process.GetCurrentProcess().Id;

try
{
// Check if the environment
string? loggingFileName = Environment.GetEnvironmentVariable(environmentVariable);

if (loggingFileName != null)
if (Environment.GetEnvironmentVariable(EnvironmentVariableName) is string loggingFileName)
{
// If the environment variable contains the path of a currently existing directory,
// then use a process-specific name for the log file and put it in that directory.
// Otherwise, assume that the environment variable specifies the name of the log file.
if (Directory.Exists(loggingFileName))
{
loggingFileName = Path.Combine(loggingFileName, $"server.{GetCurrentProcessId()}.log");
loggingFileName = Path.Combine(loggingFileName, $"server.{_processId}.log");
}

// Open allowing sharing. We allow multiple processes to log to the same file, so we use share mode to allow that.
s_loggingStream = new FileStream(loggingFileName, FileMode.OpenOrCreate, FileAccess.Write, FileShare.ReadWrite);
_loggingStream = new FileStream(loggingFileName, FileMode.OpenOrCreate, FileAccess.Write, FileShare.ReadWrite);
}
}
catch (Exception e)
{
LogException(e, "Failed to create logging stream");
}
}

/// <summary>
/// Set the logging prefix that describes our role.
/// Typically a 3-letter abbreviation. If logging happens before this, it's logged with "---".
/// </summary>
public static void Initialize(string outputPrefix)
{
s_prefix = outputPrefix;
}

/// <summary>
/// Log an exception. Also logs information about inner exceptions.
/// </summary>
public static void LogException(Exception exception, string reason)
{
if (s_loggingStream != null)
{
LogError("'{0}' '{1}' occurred during '{2}'. Stack trace:\r\n{3}", exception.GetType().Name, exception.Message, reason, exception.StackTrace);

int innerExceptionLevel = 0;

Exception? e = exception.InnerException;
while (e != null)
{
Log("Inner exception[{0}] '{1}' '{2}'. Stack trace: \r\n{3}", innerExceptionLevel, e.GetType().Name, e.Message, e.StackTrace);
e = e.InnerException;
innerExceptionLevel += 1;
}
Debug.Assert(false, e.Message);
}
}

/// <summary>
/// Log a line of text to the logging file, with string.Format arguments.
/// </summary>
public static void Log(string format, params object?[] arguments)
public void Dispose()
{
if (s_loggingStream != null)
{
Log(string.Format(format, arguments));
}
_loggingStream?.Dispose();
_loggingStream = null;
}

/// <summary>
/// Log a line of text to the logging file.
/// </summary>
/// <param name="message"></param>
public static void Log(string message)
public void Log(string message)
{
if (s_loggingStream != null)
if (_loggingStream is object)
{
string prefix = GetLoggingPrefix();

string output = prefix + message + "\r\n";
var threadId = Thread.CurrentThread.ManagedThreadId;
var prefix = $"PID={_processId} TID={threadId} Ticks={Environment.TickCount} ";
string output = prefix + message + Environment.NewLine;
byte[] bytes = Encoding.UTF8.GetBytes(output);

// Because multiple processes might be logging to the same file, we always seek to the end,
// write, and flush.
s_loggingStream.Seek(0, SeekOrigin.End);
s_loggingStream.Write(bytes, 0, bytes.Length);
s_loggingStream.Flush();
_loggingStream.Seek(0, SeekOrigin.End);
_loggingStream.Write(bytes, 0, bytes.Length);
_loggingStream.Flush();
}
}
}

public static void LogError(string message) => Log($"Error: {message}");
internal sealed class EmptyCompilerServerLogger : ICompilerServerLogger
{
public static EmptyCompilerServerLogger Instance { get; } = new EmptyCompilerServerLogger();

public static void LogError(string format, params object?[] arguments) => Log($"Error: {format}", arguments);
public bool IsLogging => false;

private static int GetCurrentProcessId()
private EmptyCompilerServerLogger()
{
var process = Process.GetCurrentProcess();
return process.Id;
}

private static int GetCurrentThreadId()
{
var thread = Thread.CurrentThread;
return thread.ManagedThreadId;
}

/// <summary>
/// Get the string that prefixes all log entries. Shows the process, thread, and time.
/// </summary>
private static string GetLoggingPrefix()
public void Log(string message)
{
return string.Format("{0} PID={1} TID={2} Ticks={3}: ", s_prefix, GetCurrentProcessId(), GetCurrentThreadId(), Environment.TickCount);
}
}
}
30 changes: 16 additions & 14 deletions src/Compilers/Core/MSBuildTask/ManagedCompiler.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -486,11 +486,12 @@ protected override int ExecuteTool(string pathToTool, string responseFileCommand
return base.ExecuteTool(pathToTool, responseFileCommands, commandLineCommands);
}

using var logger = new CompilerServerLogger();
using (_sharedCompileCts = new CancellationTokenSource())
{

CompilerServerLogger.Log($"CommandLine = '{commandLineCommands}'");
CompilerServerLogger.Log($"BuildResponseFile = '{responseFileCommands}'");
logger.Log($"CommandLine = '{commandLineCommands}'");
logger.Log($"BuildResponseFile = '{responseFileCommands}'");

var clientDir = Path.GetDirectoryName(PathToManagedTool);
if (clientDir is null || tempDir is null)
Expand Down Expand Up @@ -520,18 +521,19 @@ protected override int ExecuteTool(string pathToTool, string responseFileCommand
buildPaths,
keepAlive: null,
libEnvVariable: LibDirectoryToUse(),
logger: logger,
cancellationToken: _sharedCompileCts.Token);

responseTask.Wait(_sharedCompileCts.Token);

var response = responseTask.Result;
if (response != null)
{
ExitCode = HandleResponse(response, pathToTool, responseFileCommands, commandLineCommands);
ExitCode = HandleResponse(response, pathToTool, responseFileCommands, commandLineCommands, logger);
}
else
{
CompilerServerLogger.LogError($"Server compilation failed, falling back to {pathToTool}");
logger.LogError($"Server compilation failed, falling back to {pathToTool}");
Log.LogMessage(ErrorString.SharedCompilationFallback, pathToTool);

ExitCode = base.ExecuteTool(pathToTool, responseFileCommands, commandLineCommands);
Expand Down Expand Up @@ -615,7 +617,7 @@ private string CurrentDirectoryToUse()
/// Handle a response from the server, reporting messages and returning
/// the appropriate exit code.
/// </summary>
private int HandleResponse(BuildResponse response, string pathToTool, string responseFileCommands, string commandLineCommands)
private int HandleResponse(BuildResponse response, string pathToTool, string responseFileCommands, string commandLineCommands, ICompilerServerLogger logger)
{
if (response.Type != BuildResponse.ResponseType.Completed)
{
Expand All @@ -640,28 +642,28 @@ private int HandleResponse(BuildResponse response, string pathToTool, string res
return completedResponse.ReturnCode;

case BuildResponse.ResponseType.MismatchedVersion:
LogError("Roslyn compiler server reports different protocol version than build task.");
logError("Roslyn compiler server reports different protocol version than build task.");
return base.ExecuteTool(pathToTool, responseFileCommands, commandLineCommands);

case BuildResponse.ResponseType.IncorrectHash:
LogError("Roslyn compiler server reports different hash version than build task.");
logError("Roslyn compiler server reports different hash version than build task.");
return base.ExecuteTool(pathToTool, responseFileCommands, commandLineCommands);

case BuildResponse.ResponseType.Rejected:
case BuildResponse.ResponseType.AnalyzerInconsistency:
CompilerServerLogger.LogError($"Server rejected request {response.Type}");
logger.LogError($"Server rejected request {response.Type}");
return base.ExecuteTool(pathToTool, responseFileCommands, commandLineCommands);

default:
LogError($"Received an unrecognized response from the server: {response.Type}");
logError($"Received an unrecognized response from the server: {response.Type}");
return base.ExecuteTool(pathToTool, responseFileCommands, commandLineCommands);
}
}

internal void LogError(string message)
{
CompilerServerLogger.LogError(message);
Log.LogError(message);
void logError(string message)
{
logger.LogError(message);
Log.LogError(message);
}
}

private void LogErrorMultiline(string output)
Expand Down
Loading

0 comments on commit 2693957

Please sign in to comment.