Better client / server logging (dotnet#46079)

jaredpar · web-flow · commit f27ec979491a · 2020-07-17T12:07:17.000-07:00
diff --git a/Compilers.sln b/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
diff --git a/src/Compilers/Core/CommandLine/CompilerServerLogger.cs b/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();
diff --git a/src/Compilers/Core/MSBuildTask/CopyRefAssembly.cs b/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;
             }
 
diff --git a/src/Compilers/Core/MSBuildTask/ManagedCompiler.cs b/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);
                 }
             }
         }
diff --git a/src/Compilers/Server/VBCSCompiler/AnalyzerConsistencyChecker.cs b/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;
                 }
             }
diff --git a/src/Compilers/Server/VBCSCompiler/ServerDispatcher.cs b/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;
             }
         }
diff --git a/src/Compilers/Shared/BuildServerConnection.cs b/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;
             }

Original file line number	Diff line number	Diff line change
`@@ -79,7 +79,7 @@ public static void LogException(Exception exception, string reason)`
`79`	`79`	`{`
`80`	`80`	`if (s_loggingStream != null)`
`81`	`81`	`{`
`82`		`- Log("Exception '{0}' occurred during '{1}'. Stack trace:\r\n{2}", exception.Message, reason, exception.StackTrace);`
	`82`	`+ LogError("Exception '{0}' occurred during '{1}'. Stack trace:\r\n{2}", exception.Message, reason, exception.StackTrace);`
`83`	`83`
`84`	`84`	`int innerExceptionLevel = 0;`
`85`	`85`
`@@ -125,6 +125,10 @@ public static void Log(string message)`
`125`	`125`	`}`
`126`	`126`	`}`
`127`	`127`
	`128`	`+ public static void LogError(string message) => Log($"Error: {message}");`
	`129`	`+`
	`130`	`+ public static void LogError(string format, params object?[] arguments) => Log($"Error: {format}", arguments);`
	`131`	`+`
`128`	`132`	`private static int GetCurrentProcessId()`
`129`	`133`	`{`
`130`	`134`	`var process = Process.GetCurrentProcess();`
Original file line number	Diff line number	Diff line change
`@@ -88,8 +88,9 @@ private bool Copy()`
`88`	`88`	`}`
`89`	`89`	`catch (Exception e)`
`90`	`90`	`{`
`91`		`- Log.LogErrorWithCodeFromResources("Compiler_UnexpectedException");`
`92`		`- ManagedCompiler.LogErrorOutput(e.ToString(), Log);`
	`91`	`+ var util = new TaskLoggingHelper(this);`
	`92`	`+ util.LogErrorWithCodeFromResources("Compiler_UnexpectedException");`
	`93`	`+ util.LogErrorFromException(e, showStackTrace: true, showDetail: true, file: null);`
`93`	`94`	`return false;`
`94`	`95`	`}`
`95`	`96`
Original file line number	Diff line number	Diff line change
`@@ -16,6 +16,7 @@`
`16`	`16`	`using Microsoft.Build.Utilities;`
`17`	`17`	`using Roslyn.Utilities;`
`18`	`18`	`using Microsoft.CodeAnalysis.CommandLine;`
	`19`	`+using Microsoft.Build.Tasks;`
`19`	`20`
`20`	`21`	`namespace Microsoft.CodeAnalysis.BuildTasks`
`21`	`22`	`{`
`@@ -526,6 +527,7 @@ protected override int ExecuteTool(string pathToTool, string responseFileCommand`
`526`	`527`	`}`
`527`	`528`	`else`
`528`	`529`	`{`
	`530`	`+ CompilerServerLogger.LogError($"Server compilation failed, falling back to {pathToTool}");`
`529`	`531`	`Log.LogMessage(ErrorString.SharedCompilationFallback, pathToTool);`
`530`	`532`
`531`	`533`	`ExitCode = base.ExecuteTool(pathToTool, responseFileCommands, commandLineCommands);`
`@@ -538,8 +540,9 @@ protected override int ExecuteTool(string pathToTool, string responseFileCommand`
`538`	`540`	`}`
`539`	`541`	`catch (Exception e)`
`540`	`542`	`{`
`541`		`- Log.LogErrorWithCodeFromResources("Compiler_UnexpectedException");`
`542`		`- LogErrorOutput(e.ToString());`
	`543`	`+ var util = new TaskLoggingHelper(this);`
	`544`	`+ util.LogErrorWithCodeFromResources("Compiler_UnexpectedException");`
	`545`	`+ util.LogErrorFromException(e, showStackTrace: true, showDetail: true, file: null);`
`543`	`546`	`ExitCode = -1;`
`544`	`547`	`}`
`545`	`548`
`@@ -623,7 +626,7 @@ private int HandleResponse(BuildResponse response, string pathToTool, string res`
`623`	`626`
`624`	`627`	`if (LogStandardErrorAsError)`
`625`	`628`	`{`
`626`		`- LogErrorOutput(completedResponse.ErrorOutput);`
	`629`	`+ LogErrorMultiline(completedResponse.ErrorOutput);`
`627`	`630`	`}`
`628`	`631`	`else`
`629`	`632`	`{`
`@@ -633,37 +636,39 @@ private int HandleResponse(BuildResponse response, string pathToTool, string res`
`633`	`636`	`return completedResponse.ReturnCode;`
`634`	`637`
`635`	`638`	`case BuildResponse.ResponseType.MismatchedVersion:`
`636`		`- LogErrorOutput("Roslyn compiler server reports different protocol version than build task.");`
	`639`	`+ LogError("Roslyn compiler server reports different protocol version than build task.");`
`637`	`640`	`return base.ExecuteTool(pathToTool, responseFileCommands, commandLineCommands);`
`638`	`641`
`639`	`642`	`case BuildResponse.ResponseType.IncorrectHash:`
`640`		`- LogErrorOutput("Roslyn compiler server reports different hash version than build task.");`
	`643`	`+ LogError("Roslyn compiler server reports different hash version than build task.");`
`641`	`644`	`return base.ExecuteTool(pathToTool, responseFileCommands, commandLineCommands);`
`642`	`645`
`643`	`646`	`case BuildResponse.ResponseType.Rejected:`
`644`	`647`	`case BuildResponse.ResponseType.AnalyzerInconsistency:`
	`648`	`+ CompilerServerLogger.LogError($"Server rejected request {response.Type}");`
`645`	`649`	`return base.ExecuteTool(pathToTool, responseFileCommands, commandLineCommands);`
`646`	`650`
`647`	`651`	`default:`
`648`		`- LogErrorOutput($"Received an unrecognized response from the server: {response.Type}");`
	`652`	`+ LogError($"Received an unrecognized response from the server: {response.Type}");`
`649`	`653`	`return base.ExecuteTool(pathToTool, responseFileCommands, commandLineCommands);`
`650`	`654`	`}`
`651`	`655`	`}`
`652`	`656`
`653`		`- private void LogErrorOutput(string output)`
	`657`	`+ internal void LogError(string message)`
`654`	`658`	`{`
`655`		`- LogErrorOutput(output, Log);`
	`659`	`+ CompilerServerLogger.LogError(message);`
	`660`	`+ Log.LogError(message);`
`656`	`661`	`}`
`657`	`662`
`658`		`- internal static void LogErrorOutput(string output, TaskLoggingHelper log)`
	`663`	`+ private void LogErrorMultiline(string output)`
`659`	`664`	`{`
`660`	`665`	`string[] lines = output.Split(new string[] { Environment.NewLine }, StringSplitOptions.RemoveEmptyEntries);`
`661`	`666`	`foreach (string line in lines)`
`662`	`667`	`{`
`663`	`668`	`string trimmedMessage = line.Trim();`
`664`	`669`	`if (trimmedMessage != "")`
`665`	`670`	`{`
`666`		`- log.LogError(trimmedMessage);`
	`671`	`+ Log.LogError(trimmedMessage);`
`667`	`672`	`}`
`668`	`673`	`}`
`669`	`674`	`}`
Original file line number	Diff line number	Diff line change
`@@ -68,7 +68,7 @@ private static bool CheckCore(string baseDirectory, IEnumerable<CommandLineAnaly`
`68`	`68`	`{`
`69`	`69`	`if (!ignorableReferenceNames.Any(name => missingDependency.Name.StartsWith(name)))`
`70`	`70`	`{`
`71`		`- CompilerServerLogger.Log($"Analyzer assembly {resolvedPath} depends on '{missingDependency}' but it was not found.");`
	`71`	`+ CompilerServerLogger.LogError($"Analyzer assembly {resolvedPath} depends on '{missingDependency}' but it was not found.");`
`72`	`72`	`return false;`
`73`	`73`	`}`
`74`	`74`	`}`
`@@ -98,7 +98,7 @@ private static bool CheckCore(string baseDirectory, IEnumerable<CommandLineAnaly`
`98`	`98`
`99`	`99`	`if (resolvedPathMvid != loadedAssemblyMvid)`
`100`	`100`	`{`
`101`		`- CompilerServerLogger.Log($"Analyzer assembly {resolvedPath} has MVID '{resolvedPathMvid}' but loaded assembly '{loadedAssembly.FullName}' has MVID '{loadedAssemblyMvid}'.");`
	`101`	`+ CompilerServerLogger.LogError($"Analyzer assembly {resolvedPath} has MVID '{resolvedPathMvid}' but loaded assembly '{loadedAssembly.FullName}' has MVID '{loadedAssemblyMvid}'.");`
`102`	`102`	`return false;`
`103`	`103`	`}`
`104`	`104`	`}`
Original file line number	Diff line number	Diff line change
`@@ -288,7 +288,7 @@ private static async Task<BuildResponse> TryCompileAsync(NamedPipeClientStream p`
`288`	`288`	`}`
`289`	`289`	`else`
`290`	`290`	`{`
`291`		`- Log("Client disconnect");`
	`291`	`+ LogError("Client disconnect");`
`292`	`292`	`response = new RejectedBuildResponse($"Client disconnected");`
`293`	`293`	`}`
`294`	`294`
`@@ -382,7 +382,7 @@ internal static async Task MonitorDisconnectAsync(`
`382`	`382`	`// IOException: The server is connected to another client and the`
`383`	`383`	`// time-out period has expired.`
`384`	`384`
`385`		`- Log($"Connecting to server timed out after {timeoutMs} ms");`
	`385`	`+ LogException(e, $"Connecting to server timed out after {timeoutMs} ms");`
`386`	`386`	`return null;`
`387`	`387`	`}`
`388`	`388`	`Log("Named pipe '{0}' connected", pipeName);`
`@@ -392,7 +392,7 @@ internal static async Task MonitorDisconnectAsync(`
`392`	`392`	`// Verify that we own the pipe.`
`393`	`393`	`if (!NamedPipeUtil.CheckPipeConnectionOwnership(pipeStream))`
`394`	`394`	`{`
`395`		`- Log("Owner of named pipe is incorrect");`
	`395`	`+ LogError("Owner of named pipe is incorrect");`
`396`	`396`	`return null;`
`397`	`397`	`}`
`398`	`398`
`@@ -461,7 +461,7 @@ internal static bool TryCreateServerCore(string clientDir, string pipeName)`
`461`	`461`	`}`
`462`	`462`	`else`
`463`	`463`	`{`
`464`		`- Log("Failed to create process. GetLastError={0}", Marshal.GetLastWin32Error());`
	`464`	`+ LogError("Failed to create process. GetLastError={0}", Marshal.GetLastWin32Error());`
`465`	`465`	`}`
`466`	`466`	`return success;`
`467`	`467`	`}`