Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Make compiler server logging explicit #48557

Merged
merged 4 commits into from
Nov 20, 2020
Merged

Make compiler server logging explicit #48557

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
483eab5
Make compiler server logging explicit
jaredpar Oct 13, 2020
808060f
PR feedback
jaredpar Nov 10, 2020
d917fb2
Feedback
jaredpar Nov 19, 2020
26e90ce
Merge fixup
jaredpar Nov 20, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 2 additions & 1 deletion src/Compilers/CSharp/csc/Program.cs
View file
Open in desktop
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
Open in desktop
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
Open in desktop
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
Open in desktop
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