Better client / server logging

Compilers.sln

@@ -62,7 +62,7 @@ Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "CSharpErrorFactsGenerator",
 EndProject
 Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "CSharpSyntaxGenerator", "src\Tools\Source\CompilerGeneratorTools\Source\CSharpSyntaxGenerator\CSharpSyntaxGenerator.csproj", "{288089C5-8721-458E-BE3E-78990DAB5E2D}"
 EndProject
-Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "IOperationGenerator", "src\Tools\Source\CompilerGeneratorTools\Source\IOperationGenerator\CompilersIOperationGenerator.csproj", "{D0A79850-B32A-45E5-9FD5-D43CB345867A}"
+Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "CompilersIOperationGenerator", "src\Tools\Source\CompilerGeneratorTools\Source\IOperationGenerator\CompilersIOperationGenerator.csproj", "{D0A79850-B32A-45E5-9FD5-D43CB345867A}"
 EndProject
 Project("{778DAE3C-4631-46EA-AA77-85C1314464D9}") = "VisualBasicSyntaxGenerator", "src\Tools\Source\CompilerGeneratorTools\Source\VisualBasicSyntaxGenerator\VisualBasicSyntaxGenerator.vbproj", "{6AA96934-D6B7-4CC8-990D-DB6B9DD56E34}"
 EndProject
@@ -303,10 +303,10 @@ Global
 		{288089C5-8721-458E-BE3E-78990DAB5E2D}.Debug|Any CPU.Build.0 = Debug|x64
 		{288089C5-8721-458E-BE3E-78990DAB5E2D}.Release|Any CPU.ActiveCfg = Release|x64
 		{288089C5-8721-458E-BE3E-78990DAB5E2D}.Release|Any CPU.Build.0 = Release|x64
-		{D0A79850-B32A-45E5-9FD5-D43CB345867A}.Debug|Any CPU.ActiveCfg = Debug|x64
-		{D0A79850-B32A-45E5-9FD5-D43CB345867A}.Debug|Any CPU.Build.0 = Debug|x64
-		{D0A79850-B32A-45E5-9FD5-D43CB345867A}.Release|Any CPU.ActiveCfg = Release|x64
-		{D0A79850-B32A-45E5-9FD5-D43CB345867A}.Release|Any CPU.Build.0 = Release|x64
+		{D0A79850-B32A-45E5-9FD5-D43CB345867A}.Debug|Any CPU.ActiveCfg = Debug|Any CPU
+		{D0A79850-B32A-45E5-9FD5-D43CB345867A}.Debug|Any CPU.Build.0 = Debug|Any CPU
+		{D0A79850-B32A-45E5-9FD5-D43CB345867A}.Release|Any CPU.ActiveCfg = Release|Any CPU
+		{D0A79850-B32A-45E5-9FD5-D43CB345867A}.Release|Any CPU.Build.0 = Release|Any CPU
 		{6AA96934-D6B7-4CC8-990D-DB6B9DD56E34}.Debug|Any CPU.ActiveCfg = Debug|x64
 		{6AA96934-D6B7-4CC8-990D-DB6B9DD56E34}.Debug|Any CPU.Build.0 = Debug|x64
 		{6AA96934-D6B7-4CC8-990D-DB6B9DD56E34}.Release|Any CPU.ActiveCfg = Release|x64

src/Compilers/Core/CommandLine/CompilerServerLogger.cs

@@ -79,7 +79,7 @@ public static void LogException(Exception exception, string reason)
         {
             if (s_loggingStream != null)
             {
-                Log("Exception '{0}' occurred during '{1}'. Stack trace:\r\n{2}", exception.Message, reason, exception.StackTrace);
+                LogError("Exception '{0}' occurred during '{1}'. Stack trace:\r\n{2}", exception.Message, reason, exception.StackTrace);
 
                 int innerExceptionLevel = 0;
 
@@ -125,6 +125,10 @@ public static void Log(string message)
             }
         }
 
+        public static void LogError(string message) => Log($"Error: {message}");
+
+        public static void LogError(string format, params object?[] arguments) => Log($"Error: {format}", arguments);
+
         private static int GetCurrentProcessId()
         {
             var process = Process.GetCurrentProcess();

src/Compilers/Core/MSBuildTask/CopyRefAssembly.cs

@@ -88,8 +88,9 @@ private bool Copy()
             }
             catch (Exception e)
             {
-                Log.LogErrorWithCodeFromResources("Compiler_UnexpectedException");
-                ManagedCompiler.LogErrorOutput(e.ToString(), Log);
+                var util = new TaskLoggingHelper(this);
+                util.LogErrorWithCodeFromResources("Compiler_UnexpectedException");
+                util.LogErrorFromException(e, showStackTrace: true, showDetail: true, file: null);
                 return false;
             }
 

src/Compilers/Core/MSBuildTask/ManagedCompiler.cs

@@ -16,6 +16,7 @@
 using Microsoft.Build.Utilities;
 using Roslyn.Utilities;
 using Microsoft.CodeAnalysis.CommandLine;
+using Microsoft.Build.Tasks;
 
 namespace Microsoft.CodeAnalysis.BuildTasks
 {
@@ -526,6 +527,7 @@ protected override int ExecuteTool(string pathToTool, string responseFileCommand
                     }
                     else
                     {
+                        CompilerServerLogger.LogError($"Server compilation failed, falling back to {pathToTool}");
                         Log.LogMessage(ErrorString.SharedCompilationFallback, pathToTool);
 
                         ExitCode = base.ExecuteTool(pathToTool, responseFileCommands, commandLineCommands);
@@ -538,8 +540,9 @@ protected override int ExecuteTool(string pathToTool, string responseFileCommand
             }
             catch (Exception e)
             {
-                Log.LogErrorWithCodeFromResources("Compiler_UnexpectedException");
-                LogErrorOutput(e.ToString());
+                var util = new TaskLoggingHelper(this);
+                util.LogErrorWithCodeFromResources("Compiler_UnexpectedException");
+                util.LogErrorFromException(e, showStackTrace: true, showDetail: true, file: null);
                 ExitCode = -1;
             }
 
@@ -623,7 +626,7 @@ private int HandleResponse(BuildResponse response, string pathToTool, string res
 
                     if (LogStandardErrorAsError)
                     {
-                        LogErrorOutput(completedResponse.ErrorOutput);
+                        LogErrorMultiline(completedResponse.ErrorOutput);
                     }
                     else
                     {
@@ -633,37 +636,39 @@ private int HandleResponse(BuildResponse response, string pathToTool, string res
                     return completedResponse.ReturnCode;
 
                 case BuildResponse.ResponseType.MismatchedVersion:
-                    LogErrorOutput("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:
-                    LogErrorOutput("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}");
                     return base.ExecuteTool(pathToTool, responseFileCommands, commandLineCommands);
 
                 default:
-                    LogErrorOutput($"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);
             }
         }
 
-        private void LogErrorOutput(string output)
+        internal void LogError(string message)
         {
-            LogErrorOutput(output, Log);
+            CompilerServerLogger.LogError(message);
+            Log.LogError(message);
         }
 
-        internal static void LogErrorOutput(string output, TaskLoggingHelper log)
+        private void LogErrorMultiline(string output)
         {
             string[] lines = output.Split(new string[] { Environment.NewLine }, StringSplitOptions.RemoveEmptyEntries);
             foreach (string line in lines)
             {
                 string trimmedMessage = line.Trim();
                 if (trimmedMessage != "")
                 {
-                    log.LogError(trimmedMessage);
+                    Log.LogError(trimmedMessage);
                 }
             }
         }

src/Compilers/Server/VBCSCompiler/AnalyzerConsistencyChecker.cs

@@ -68,7 +68,7 @@ private static bool CheckCore(string baseDirectory, IEnumerable<CommandLineAnaly
                 {
                     if (!ignorableReferenceNames.Any(name => missingDependency.Name.StartsWith(name)))
                     {
-                        CompilerServerLogger.Log($"Analyzer assembly {resolvedPath} depends on '{missingDependency}' but it was not found.");
+                        CompilerServerLogger.LogError($"Analyzer assembly {resolvedPath} depends on '{missingDependency}' but it was not found.");
                         return false;
                     }
                 }
@@ -98,7 +98,7 @@ private static bool CheckCore(string baseDirectory, IEnumerable<CommandLineAnaly
 
                 if (resolvedPathMvid != loadedAssemblyMvid)
                 {
-                    CompilerServerLogger.Log($"Analyzer assembly {resolvedPath} has MVID '{resolvedPathMvid}' but loaded assembly '{loadedAssembly.FullName}' has MVID '{loadedAssemblyMvid}'.");
+                    CompilerServerLogger.LogError($"Analyzer assembly {resolvedPath} has MVID '{resolvedPathMvid}' but loaded assembly '{loadedAssembly.FullName}' has MVID '{loadedAssemblyMvid}'.");
                     return false;
                 }
             }

src/Compilers/Server/VBCSCompiler/ServerDispatcher.cs

@@ -294,17 +294,21 @@ private void HandleCompletedConnections()
                 {
                     case CompletionReason.CompilationCompleted:
                     case CompletionReason.CompilationNotStarted:
+                        CompilerServerLogger.Log("Client completed");
                         // These are all normal shutdown states.  Nothing to do here.
                         break;
                     case CompletionReason.ClientDisconnect:
                         // Have to assume the worst here which is user pressing Ctrl+C at the command line and
                         // hence wanting all compilation to end.
-                        CompilerServerLogger.Log("Unexpected client disconnect. Shutting down server");
+                        CompilerServerLogger.LogError("Unexpected client disconnect. Shutting down server");
                         shutdown = true;
                         break;
                     case CompletionReason.ClientException:
+                        CompilerServerLogger.LogError($"Unexpected client exception. Shutting down server");
+                        shutdown = true;
+                        break;
                     case CompletionReason.ClientShutdownRequest:
-                        CompilerServerLogger.Log($"Unexpected client completion: {connectionData.CompletionReason}. Shutting down server");
+                        CompilerServerLogger.Log($"Client requesting server shutdown");
                         shutdown = true;
                         break;
                     default:
@@ -316,6 +320,7 @@ private void HandleCompletedConnections()
 
             if (shutdown)
             {
+                CompilerServerLogger.Log($"Shutting down server");
                 _state = State.ShuttingDown;
             }
         }

src/Compilers/Shared/BuildServerConnection.cs

@@ -288,7 +288,7 @@ private static async Task<BuildResponse> TryCompileAsync(NamedPipeClientStream p
                 }
                 else
                 {
-                    Log("Client disconnect");
+                    LogError("Client disconnect");
                     response = new RejectedBuildResponse($"Client disconnected");
                 }
 
@@ -382,7 +382,7 @@ internal static async Task MonitorDisconnectAsync(
                     // IOException: The server is connected to another client and the
                     //              time-out period has expired.
 
-                    Log($"Connecting to server timed out after {timeoutMs} ms");
+                    LogException(e, $"Connecting to server timed out after {timeoutMs} ms");
                     return null;
                 }
                 Log("Named pipe '{0}' connected", pipeName);
@@ -392,7 +392,7 @@ internal static async Task MonitorDisconnectAsync(
                 // Verify that we own the pipe.
                 if (!NamedPipeUtil.CheckPipeConnectionOwnership(pipeStream))
                 {
-                    Log("Owner of named pipe is incorrect");
+                    LogError("Owner of named pipe is incorrect");
                     return null;
                 }
 
@@ -461,7 +461,7 @@ internal static bool TryCreateServerCore(string clientDir, string pipeName)
                 }
                 else
                 {
-                    Log("Failed to create process. GetLastError={0}", Marshal.GetLastWin32Error());
+                    LogError("Failed to create process. GetLastError={0}", Marshal.GetLastWin32Error());
                 }
                 return success;
             }