From 88bd81b7da7d8451d5796542d5392f9ebacf658f Mon Sep 17 00:00:00 2001 From: Jared Parsons Date: Wed, 15 Jul 2020 16:42:54 -0700 Subject: [PATCH] Clean up compiler logging (#46012) Clean up compiler logging The compiler logging support primarily helped with identifying issues with the underlying protocol. That was an area of problem in the initial compiler server development and a sensible logging scenario. Now though the underlying protocol isn't really an issue for the server. The bigger issue is tracking the underlying state transitions of the server and the reasons for making such transitions. This PR moves our logging to match this new reality. --- .../Core/CommandLine/BuildProtocol.cs | 68 +++++++++---------- .../VBCSCompiler/CompilerRequestHandler.cs | 28 ++++---- .../VBCSCompiler/NamedPipeClientConnection.cs | 30 ++------ .../Server/VBCSCompiler/ServerDispatcher.cs | 3 + .../CompilerServerApiTest.cs | 2 +- src/Compilers/Shared/BuildServerConnection.cs | 20 +++--- 6 files changed, 64 insertions(+), 87 deletions(-) diff --git a/src/Compilers/Core/CommandLine/BuildProtocol.cs b/src/Compilers/Core/CommandLine/BuildProtocol.cs index 0a20e7f6db1..f0389f53812 100644 --- a/src/Compilers/Core/CommandLine/BuildProtocol.cs +++ b/src/Compilers/Core/CommandLine/BuildProtocol.cs @@ -82,11 +82,12 @@ internal class BuildRequest { Debug.Assert(!string.IsNullOrWhiteSpace(compilerHash), "CompilerHash is required to send request to the build server"); - Log("Creating BuildRequest"); - Log($"Working directory: {workingDirectory}"); - Log($"Temp directory: {tempDirectory}"); - Log($"Lib directory: {libDirectory ?? "null"}"); - Log($"Compiler hash: {compilerHash}"); + 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(requestLength); @@ -108,7 +109,6 @@ internal class BuildRequest for (int i = 0; i < args.Count; ++i) { var arg = args[i]; - Log($"argument[{i}] = {arg}"); requestArgs.Add(new Argument(ArgumentId.CommandLineArgument, i, arg)); } @@ -118,7 +118,7 @@ internal class BuildRequest public static BuildRequest CreateShutdown() { var requestArgs = new[] { new Argument(ArgumentId.Shutdown, argumentIndex: 0, value: "") }; - return new BuildRequest(BuildProtocolConstants.ProtocolVersion, RequestLanguage.CSharpCompile, GetCommitHash(), requestArgs); + return new BuildRequest(BuildProtocolConstants.ProtocolVersion, RequestLanguage.CSharpCompile, GetCommitHash() ?? "", requestArgs); } /// @@ -127,19 +127,17 @@ public static BuildRequest CreateShutdown() /// The total request size must be less than 1MB. /// /// null if the Request was too large, the Request otherwise. - public static async Task ReadAsync(Stream inStream, CancellationToken cancellationToken) + public static async Task ReadAsync(Stream inStream, CancellationToken cancellationToken) { // Read the length of the request var lengthBuffer = new byte[4]; - Log("Reading length of request"); await ReadAllAsync(inStream, lengthBuffer, 4, cancellationToken).ConfigureAwait(false); var length = BitConverter.ToInt32(lengthBuffer, 0); // Back out if the request is > 1MB if (length > 0x100000) { - Log("Request is over 1MB in length, cancelling read."); - return null; + throw new ArgumentException("Request is over 1MB in length"); } cancellationToken.ThrowIfCancellationRequested(); @@ -150,7 +148,6 @@ public static BuildRequest CreateShutdown() cancellationToken.ThrowIfCancellationRequested(); - Log("Parsing request"); // Parse the request into the Request data structure. using (var reader = new BinaryReader(new MemoryStream(requestBuffer), Encoding.Unicode)) { @@ -182,8 +179,6 @@ public async Task WriteAsync(Stream outStream, CancellationToken cancellationTok using (var memoryStream = new MemoryStream()) using (var writer = new BinaryWriter(memoryStream, Encoding.Unicode)) { - // Format the request. - Log("Formatting request"); writer.Write(ProtocolVersion); writer.Write((uint)Language); writer.Write(CompilerHash); @@ -203,17 +198,12 @@ public async Task WriteAsync(Stream outStream, CancellationToken cancellationTok // Back out if the request is > 1 MB if (memoryStream.Length > 0x100000) { - Log("Request is over 1MB in length, cancelling write"); - throw new ArgumentOutOfRangeException(); + throw new ArgumentOutOfRangeException("Request is over 1MB in length"); } - // Send the request to the server - Log("Writing length of request."); await outStream.WriteAsync(BitConverter.GetBytes(length), 0, 4, cancellationToken).ConfigureAwait(false); - Log("Writing request of size {0}", length); - // Write the request memoryStream.Position = 0; await memoryStream.CopyToAsync(outStream, bufferSize: length, cancellationToken: cancellationToken).ConfigureAwait(false); } @@ -311,8 +301,6 @@ public enum ResponseType using (var memoryStream = new MemoryStream()) using (var writer = new BinaryWriter(memoryStream, Encoding.Unicode)) { - // Format the response - Log("Formatting Response"); writer.Write((int)Type); AddResponseBody(writer); @@ -325,7 +313,6 @@ public enum ResponseType // Write the length of the response int length = checked((int)memoryStream.Length); - Log("Writing response length"); // There is no way to know the number of bytes written to // the pipe stream. We just have to assume all of them are written. await outStream.WriteAsync(BitConverter.GetBytes(length), @@ -333,8 +320,6 @@ public enum ResponseType 4, cancellationToken).ConfigureAwait(false); - // Write the response - Log("Writing response of size {0}", length); memoryStream.Position = 0; await memoryStream.CopyToAsync(outStream, bufferSize: length, cancellationToken: cancellationToken).ConfigureAwait(false); } @@ -350,14 +335,12 @@ public enum ResponseType /// public static async Task ReadAsync(Stream stream, CancellationToken cancellationToken = default(CancellationToken)) { - Log("Reading response length"); // Read the response length var lengthBuffer = new byte[4]; await ReadAllAsync(stream, lengthBuffer, 4, cancellationToken).ConfigureAwait(false); var length = BitConverter.ToUInt32(lengthBuffer, 0); // Read the response - Log("Reading response of length {0}", length); var responseBuffer = new byte[length]; await ReadAllAsync(stream, responseBuffer, @@ -381,7 +364,7 @@ public static async Task ReadAsync(Stream stream, CancellationTok case ResponseType.Shutdown: return ShutdownBuildResponse.Create(reader); case ResponseType.Rejected: - return new RejectedBuildResponse(); + return RejectedBuildResponse.Create(reader); default: throw new InvalidOperationException("Received invalid response type from server."); } @@ -505,13 +488,30 @@ internal sealed class AnalyzerInconsistencyBuildResponse : BuildResponse internal sealed class RejectedBuildResponse : BuildResponse { + public string Reason; + public override ResponseType Type => ResponseType.Rejected; + public RejectedBuildResponse(string reason) + { + Reason = reason; + } + /// /// AnalyzerInconsistency has no body. /// /// - protected override void AddResponseBody(BinaryWriter writer) { } + protected override void AddResponseBody(BinaryWriter writer) + { + WriteLengthPrefixedString(writer, Reason); + } + + public static RejectedBuildResponse Create(BinaryReader reader) + { + var reason = ReadLengthPrefixedString(reader); + Debug.Assert(reason is object); + return new RejectedBuildResponse(reason); + } } // The id numbers below are just random. It's useful to use id numbers @@ -592,14 +592,13 @@ public static void WriteLengthPrefixedString(BinaryWriter writer, string? value) /// Reads the value of of the assembly is defined in /// /// The hash value of the current assembly or an empty string - public static string GetCommitHash() + public static string? GetCommitHash() { var hashAttributes = typeof(BuildRequest).Assembly.GetCustomAttributes(); var hashAttributeCount = hashAttributes.Count(); if (hashAttributeCount != 1) { - Log($"Error reading CommitHashAttribute. Exactly 1 attribute is required, found {hashAttributeCount}"); - return string.Empty; + return null; } return hashAttributes.Single().Hash; } @@ -616,21 +615,16 @@ public static string GetCommitHash() int totalBytesRead = 0; do { - Log("Attempting to read {0} bytes from the stream", - count - totalBytesRead); int bytesRead = await stream.ReadAsync(buffer, totalBytesRead, count - totalBytesRead, cancellationToken).ConfigureAwait(false); if (bytesRead == 0) { - Log("Unexpected -- read 0 bytes from the stream."); throw new EndOfStreamException("Reached end of stream before end of read."); } - Log("Read {0} bytes", bytesRead); totalBytesRead += bytesRead; } while (totalBytesRead < count); - Log("Finished read"); } } } diff --git a/src/Compilers/Server/VBCSCompiler/CompilerRequestHandler.cs b/src/Compilers/Server/VBCSCompiler/CompilerRequestHandler.cs index 559c9703211..c8865427d46 100644 --- a/src/Compilers/Server/VBCSCompiler/CompilerRequestHandler.cs +++ b/src/Compilers/Server/VBCSCompiler/CompilerRequestHandler.cs @@ -96,27 +96,22 @@ public bool TryCreateCompiler(RunRequest request, out CommonCompiler compiler) public BuildResponse RunCompilation(RunRequest request, CancellationToken cancellationToken) { - Log($"CurrentDirectory = '{request.CurrentDirectory}'"); - Log($"LIB = '{request.LibDirectory}'"); - for (int i = 0; i < request.Arguments.Length; ++i) - { - Log($"Argument[{i}] = '{request.Arguments[i]}'"); - } + Log($@" +Run Compilation + CurrentDirectory = '{request.CurrentDirectory} + LIB = '{request.LibDirectory}'"); // Compiler server must be provided with a valid temporary directory in order to correctly // isolate signing between compilations. if (string.IsNullOrEmpty(request.TempDirectory)) { - Log($"Rejecting build due to missing temp directory"); - return new RejectedBuildResponse(); + return new RejectedBuildResponse("Missing temp directory"); } CommonCompiler compiler; if (!TryCreateCompiler(request, out compiler)) { - // We can't do anything with a request we don't know about. - Log($"Got request with id '{request.Language}'"); - return new RejectedBuildResponse(); + return new RejectedBuildResponse($"Cannot create compiler for language id {request.Language}"); } bool utf8output = compiler.Arguments.Utf8Output; @@ -125,11 +120,16 @@ public BuildResponse RunCompilation(RunRequest request, CancellationToken cancel return new AnalyzerInconsistencyBuildResponse(); } - Log($"****Running {request.Language} compiler..."); + Log($"Begin {request.Language} compiler run"); TextWriter output = new StringWriter(CultureInfo.InvariantCulture); int returnCode = compiler.Run(output, cancellationToken); - Log($"****{request.Language} Compilation complete.\r\n****Return code: {returnCode}\r\n****Output:\r\n{output.ToString()}\r\n"); - return new CompletedBuildResponse(returnCode, utf8output, output.ToString()); + var outputString = output.ToString(); + Log(@$" +End {request.Language} Compilation complete. +Return code: {returnCode} +Output: +{outputString}"); + return new CompletedBuildResponse(returnCode, utf8output, outputString); } } } diff --git a/src/Compilers/Server/VBCSCompiler/NamedPipeClientConnection.cs b/src/Compilers/Server/VBCSCompiler/NamedPipeClientConnection.cs index 35e1a5597e1..1605bf46249 100644 --- a/src/Compilers/Server/VBCSCompiler/NamedPipeClientConnection.cs +++ b/src/Compilers/Server/VBCSCompiler/NamedPipeClientConnection.cs @@ -112,8 +112,7 @@ public void Close() // The client connection failing to close isn't fatal to the server process. It is simply a client // for which we can no longer communicate and that's okay because the Close method indicates we are // done with the client already. - var msg = string.Format($"Pipe {LoggingIdentifier}: Error closing pipe."); - CompilerServerLogger.LogException(e, msg); + CompilerServerLogger.LogException(e, $"Pipe {LoggingIdentifier}: Error closing pipe."); } } @@ -124,14 +123,12 @@ public async Task HandleConnectionAsync(bool allowCompilationReq BuildRequest request; try { - Log("Begin reading request."); request = await BuildRequest.ReadAsync(_stream, cancellationToken).ConfigureAwait(false); ValidateBuildRequest(request); - Log("End reading request."); } catch (Exception e) { - LogException(e, "Error reading build request."); + CompilerServerLogger.LogException(e, "Error reading build request."); return new ConnectionData(CompletionReason.CompilationNotStarted); } @@ -149,7 +146,7 @@ public async Task HandleConnectionAsync(bool allowCompilationReq } else if (!allowCompilationRequests) { - return await HandleRejectedRequestAsync(cancellationToken).ConfigureAwait(false); + return await HandleRejectedRequestAsync("Compilation requests not allowed at this time", cancellationToken).ConfigureAwait(false); } else { @@ -181,10 +178,8 @@ private async Task HandleCompilationRequestAsync(BuildRequest re try { - Log("Begin writing response."); await response.WriteAsync(_stream, cancellationToken).ConfigureAwait(false); reason = CompletionReason.CompilationCompleted; - Log("End writing response."); } catch { @@ -216,9 +211,9 @@ private async Task HandleIncorrectHashRequestAsync(CancellationT return new ConnectionData(CompletionReason.CompilationNotStarted); } - private async Task HandleRejectedRequestAsync(CancellationToken cancellationToken) + private async Task HandleRejectedRequestAsync(string reason, CancellationToken cancellationToken) { - var response = new RejectedBuildResponse(); + var response = new RejectedBuildResponse(reason); await response.WriteAsync(_stream, cancellationToken).ConfigureAwait(false); return new ConnectionData(CompletionReason.CompilationNotStarted); } @@ -266,13 +261,8 @@ private Task ServeBuildRequestAsync(BuildRequest buildRequest, Ca { Func func = () => { - // Do the compilation - Log("Begin compilation"); - var request = BuildProtocolUtil.GetRunRequest(buildRequest); var response = _compilerServerHost.RunCompilation(request, cancellationToken); - - Log("End compilation"); return response; }; @@ -280,15 +270,5 @@ private Task ServeBuildRequestAsync(BuildRequest buildRequest, Ca task.Start(); return task; } - - private void Log(string message) - { - CompilerServerLogger.Log("Client {0}: {1}", _loggingIdentifier, message); - } - - private void LogException(Exception e, string message) - { - CompilerServerLogger.LogException(e, string.Format("Client {0}: {1}", _loggingIdentifier, message)); - } } } diff --git a/src/Compilers/Server/VBCSCompiler/ServerDispatcher.cs b/src/Compilers/Server/VBCSCompiler/ServerDispatcher.cs index 762a7457559..4a7039c97e6 100644 --- a/src/Compilers/Server/VBCSCompiler/ServerDispatcher.cs +++ b/src/Compilers/Server/VBCSCompiler/ServerDispatcher.cs @@ -229,6 +229,7 @@ private void HandleCompletedListenTask(CancellationToken cancellationToken) private void HandleCompletedTimeoutTask() { + CompilerServerLogger.Log("Timeout triggered. Shutting down server."); _diagnosticListener.KeepAliveReached(); _listenCancellationTokenSource.Cancel(); _timeoutTask = null; @@ -298,10 +299,12 @@ private void HandleCompletedConnections() 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"); shutdown = true; break; case CompletionReason.ClientException: case CompletionReason.ClientShutdownRequest: + CompilerServerLogger.Log($"Unexpected client completion: {connectionData.CompletionReason}. Shutting down server"); shutdown = true; break; default: diff --git a/src/Compilers/Server/VBCSCompilerTests/CompilerServerApiTest.cs b/src/Compilers/Server/VBCSCompilerTests/CompilerServerApiTest.cs index 1299275b4c5..e101d9bdd63 100644 --- a/src/Compilers/Server/VBCSCompilerTests/CompilerServerApiTest.cs +++ b/src/Compilers/Server/VBCSCompilerTests/CompilerServerApiTest.cs @@ -512,7 +512,7 @@ public async Task CancelWillCancelCompilation() } cancellationToken.WaitHandle.WaitOne(); - return new RejectedBuildResponse(); + return new RejectedBuildResponse(""); }; var list = new List>(); diff --git a/src/Compilers/Shared/BuildServerConnection.cs b/src/Compilers/Shared/BuildServerConnection.cs index a6081eb936b..17d308b92b3 100644 --- a/src/Compilers/Shared/BuildServerConnection.cs +++ b/src/Compilers/Shared/BuildServerConnection.cs @@ -113,14 +113,14 @@ internal sealed class BuildServerConnection CreateServerFunc createServerFunc, CancellationToken cancellationToken) { - if (pipeName == null) + if (pipeName is null) { - return new RejectedBuildResponse(); + throw new ArgumentException(nameof(pipeName)); } if (buildPaths.TempDirectory == null) { - return new RejectedBuildResponse(); + throw new ArgumentException(nameof(buildPaths)); } // early check for the build hash. If we can't find it something is wrong; no point even trying to go to the server @@ -132,21 +132,21 @@ internal sealed class BuildServerConnection var pipeTask = tryConnectToServer(pipeName, buildPaths, timeoutOverride, createServerFunc, cancellationToken); if (pipeTask is null) { - return new RejectedBuildResponse(); + return new RejectedBuildResponse("Failed to connect to server"); } else { var pipe = await pipeTask.ConfigureAwait(false); if (pipe is null) { - return new RejectedBuildResponse(); + return new RejectedBuildResponse("Failed to connect to server"); } else { var request = BuildRequest.Create(language, buildPaths.WorkingDirectory, buildPaths.TempDirectory, - BuildProtocolConstants.GetCommitHash(), + BuildProtocolConstants.GetCommitHash() ?? "", arguments, keepAlive, libEnvVariable); @@ -259,7 +259,7 @@ internal sealed class BuildServerConnection catch (Exception e) { LogException(e, "Error writing build request."); - return new RejectedBuildResponse(); + return new RejectedBuildResponse($"Error writing build request: {e.Message}"); } // Wait for the compilation and a monitor to detect if the server disconnects @@ -283,13 +283,13 @@ internal sealed class BuildServerConnection catch (Exception e) { LogException(e, "Error reading response"); - response = new RejectedBuildResponse(); + response = new RejectedBuildResponse($"Error reading response: {e.Message}"); } } else { - Log("Server disconnect"); - response = new RejectedBuildResponse(); + Log("Client disconnect"); + response = new RejectedBuildResponse($"Client disconnected"); } // Cancel whatever task is still around -- GitLab