Conversation
The goal if this PR is to change the logging so that: 1. It's easier to identify the process writing the message. The prefix for messages will be prefixed with either "VBCSCompiler" or "MSBuild <process id>". 1. Add a `Guid` to a logical build request that is included in many messages. This will make it easier to track requests as they travel between the MSBuild and VBCSCompiler processes. 1. Ensure all failure states have an explicit log call The motivation for this change is we are seeing the compiler server crash in build correctness and source build legs. From the log it's hard to see what is happening. The failure is essentially silent. This is an attempt to get more data so we can see what is actually going on during failure.
|
@dotnet/roslyn-compiler PTAL |
| /// ---------------------------------------------------- | ||
| /// Length Integer 4 | ||
| /// ProtocolVersion Integer 4 | ||
| /// RequestId Guid 16 |
There was a problem hiding this comment.
In the early days of the compiler server the ProtocolVersion field was intended to be a versioning mechanism. Every time we changed the protocol we update this number and make sure that we maintain compatibility. Later on though we added the compiler hash to the build protocol and both sides reject messages where the hashes don't match. This effectively renders the ProtocolVersion field meaningless hence I've removed it as a part of adding RequestId in.
| /// A value which can be used to identify this connection for logging purposes only. It has | ||
| /// no guarantee of uniqueness. | ||
| /// </summary> | ||
| string LoggingIdentifier { get; } |
There was a problem hiding this comment.
This field was used to identify client connections for logging purposes in the server. Now that there is a Guid that tracks the connection in both client and server this just isn't needed anymore.
| Guid? requestId = null) | ||
| { | ||
| ProtocolVersion = protocolVersion; | ||
| RequestId = requestId ?? Guid.Empty; |
There was a problem hiding this comment.
What are the times we'd expect the request id to be empty?
There was a problem hiding this comment.
When the build is invoked via test code. There isn't much value in tracking the requests there that I could see.
|
|
||
| using var logger = new CompilerServerLogger(); | ||
| return BuildClient.Run(args, RequestLanguage.CSharpCompile, Csc.Run, logger); | ||
| var requestId = Guid.NewGuid(); |
There was a problem hiding this comment.
It seems like the only time we aren't generating a new request ID per logger is in VBCSCompiler, but it doensn't seem to call any of the log-with-id methods anyway.
Would it make more sense to just have the logger make a new Guid when you create it, and have it append to the log messages, rather than making the clients of the logger responsible for tracking it?
There was a problem hiding this comment.
There are two types of IDs now:
- ID of the instance of CompilerServer logger. This is generally a named instance which makes it easy for us to know which process is writing the log entry.
- ID of an individual compiler request. This is generated at the MSBuild and command line compiler layer. This ID allows us to track a request, by simple text search in the log, as the request pings between the client and compiler server. Particularly it lets us track back a failure to the original request and lets us see where exactly the request failed.
|
/azp run |
|
Azure Pipelines successfully started running 3 pipeline(s). |
|
/azp run |
|
Azure Pipelines successfully started running 3 pipeline(s). |
| finally { | ||
| if ($enableDumps) { | ||
| $key = "HKLM:\\SOFTWARE\Microsoft\Windows\Windows Error Reporting\LocalDumps" | ||
| Remove-ItemProperty -Path $key -Name 'DumpType' |
There was a problem hiding this comment.
Should we remember the original values instead?
Also, I'm not sure what level of isolation we get in Azure. Do we risk impacting other builds by changing global/machine settings? #Closed
There was a problem hiding this comment.
The azure machines are assumed to reset items like this between runs. This pattern of set then unset is used in other areas like RunTests which we do in CI. #Closed
| try | ||
| { | ||
| using var logger = new CompilerServerLogger(); | ||
| using var logger = new CompilerServerLogger($"MSBuild {Process.GetCurrentProcess().Id}"); |
There was a problem hiding this comment.
Do we really need to include the process ID into the identifier string, since CompilerServerLogger already captures the process ID? #Closed
There was a problem hiding this comment.
The CompilerServerLogger only uses the process ID when generating the name for the log file on disk, it doesn't actually use that ID within the log. The use of the process ID here is important because there are multiple MSBuild process instances in the build and we want to differentiate between them. Unlike VBSCompiler of which there is one hence not a lot of value in dumping that in the log. #Closed
| // It is okay for this call to fail. Errors will be reflected in the | ||
| // IsConnected property which will be read on the next iteration of the | ||
| logger.LogException(e, $"Error poking pipe {identifier}."); | ||
| logger.LogException(e, $"Error poking pipe {requestId}."); |
There was a problem hiding this comment.
nit: would it be worthwhile to have the logger handle the requestId (add it to the log) so that we don't have to pass it around in so many places that already have the logger? Or do the requestId and logger have different lifetimes? #Closed
There was a problem hiding this comment.
Mm... I see that for VBCSCompiler we don't create the requestId at the same time that we create the logger, so my proposal probably wouldn't work.
In reply to: 612732135 [](ancestors = 612732135)
There was a problem hiding this comment.
That wouldn't work though. The intent of the request id is to track a compilation request across processes. The request originates in MSBuild, is passed to VBCSCompiler, then back to MSBuild once the request completes. There is no way to generate this before hand on both sides of the pipe. #Closed
| } | ||
| catch (Exception ex) | ||
| { | ||
| Logger.LogException(ex, $"Running compilation for {request.RequestId}"); |
There was a problem hiding this comment.
Is the message correct? #Closed
There was a problem hiding this comment.
Yes. The second argument to LogException describes the operation which was occurring when the exception was thrown. #Closed
jcouv
left a comment
There was a problem hiding this comment.
Done with review pass (iteration 3)
|
Based on the review comments it seems I haven't done a good job of explaining what I'm trying to accomplish here. A compilation event is a muli-process problem for C# / VB. The MSBuild process (of which there are multiple) begins the compilation event by constructing a message that it sends to the VBCSCompiler process (of which there is one). The compiler receives the request, kicks off a The log file contains messages from all these different MSBuild processes and all of the threads within VBCSCompiler interleaved. The only identifying marker for message in the log is the process and thread ID. That means reading a log file requires you to figure out which PID maps to which process (MSBuild or VBCSCompiler) and which TID within specific PID (the VBCSCompiler) maps to a given compilation event. That doesn't help a lot thouh though with the core problem which is typically trying to find the compilation that failed then look at all of the log entries for that compilation. Basically filter the log down to all of the events for a compilation and see where it went wrong. This PR attempts to address that by doing the following:
Below is a sample of how the log file looks after this change. Notice that |
| public static int Main(string[] args) | ||
| { | ||
| using var logger = new CompilerServerLogger(); | ||
| using var logger = new CompilerServerLogger("VBCSCompiler"); |
There was a problem hiding this comment.
If I did that though how would I introduce typos into my PRs? #Closed
The goal if this PR is to change the logging so that:
for messages will be prefixed with either "VBCSCompiler" or "MSBuild
".
Guidto a logical build request that is included in manymessages. This will make it easier to track requests as they travel
between the MSBuild and VBCSCompiler processes.
The motivation for this change is we are seeing the compiler server
crash in build correctness and source build legs. From the log it's hard
to see what is happening. The failure is essentially silent. This is an
attempt to get more data so we can see what is actually going on during
failure.