What are "logging tokens"?

First some historical background, although this information is not really relevant to what I've done with Roslyn.

I'm a firm believer in the usefulness of having lots of diagnostic logging embedded in a program. When I first started working with C# (long, long ago) I used Apache log4net for a while. Then I wrote a wrapper for log4net. Then I took a look at NLog. And then I ended up doing what I so often do; I decided to do it myself, and wrote my own logging module for C#, with exactly the facilities I wanted, and without the clutter of lots of other facilities that I didn't want.

I also added some code to the C# preprocessor program that I use for several purposes to also support "logging tokens", and to maintain a little .xml file for each project with log token vs. method name information. So when I add a logging statement to my program I write it like this, for example:

_cLog.Debug(0x0fu, typeof(TSettings), settingsFileName);

My C# preprocessor program recognizes the string "0x0fu" and replaces it with a unique random value, modifying the C# source file so the replacement is "permanent".

_cLog.Debug(0x11e930cu, typeof(TSettings), settingsFileName);

This unique log token value is a part of the logging message, and my log viewer program can use the .xml files produced by the preprocessor program to display the name of the method that the call to the logging code is in.

ModRos 14 Snap1Incidentally, if you're curious about how my logging program obtains the relative stack depth so the viewer program can show the method names with indentation, see here.

Also incidentally, there is an official "authorized" non-reflection way of getting a method name at run time, at least since .Net Framework 4.5 - see here. But at the time I implemented the above logging module I was sticking to being .Net Framework 2.0 compatible, and anyway, to be honest, I wasn't aware of the [CallerMemberName] attribute back then.

Adding a logging tokens facility to Roslyn

Given that I do have something that works, why am I doing it all over again as a modification to Roslyn? Mostly because I'd like to phase out my C# preprocessor program (and also my post-build program, where I'm currently doing obfuscation). If this whole Roslyn modification project works out, then all my C# compilation-related processing can be consolidated in the C# compiler, where it belongs. At least, I think that's where it belongs - time will tell, and I may end up deciding that modifying Roslyn was a mistake.

Here's how I'm implementing log tokens in Roslyn. The above logging statement will have to be manually (or semi-automatically) rewritten as follows, a one-time operation:

_cLog.Debug(0 /*LogToken*/, typeof(TSettings), settingsFileName);

The Roslyn syntax tree contains everything about the C# source program, including what they call "trivia". So what I've done is to add code to the IL emitting phase of Roslyn so it recognizes a "0" syntax token followed by a trivia token for a single blank followed by a multi-line comment trivia token for the text "/*LogToken*/". When it recognizes this in the C# program it determines if a log token corresponding to this location in the program has already been generated, and if not it "generates" a token and persists the information in a LiteDB database, along with other "Project Yacks" metadata for the program. And in both cases (newly-discovered log token or previously encountered log token) it emits an IL opcode to load the log token value instead of zero.

In the next couple sections I'll show some of this code.

src\Compilers\CSharp\Portable\CodeGen\EmitExpression.Yacks.cs

This is a source file added to the CSharpCodeAnalysis project. It was previously mentioned here and here, back when I was just getting started with modifying Roslyn, and had added the facility to "disguise" string constants.

/// <summary> /// Method to either do standard processing for a constant expression value, or to emit a /// ldstr opcode for a disguised string because we are processing the constructor of one of /// the static objects that implements disguised strings, or to emit a Ldc_i4 opcode and a /// placeholder token to implement a logging token. /// </summary> private void EmitConstantValue(ConstantValue constantValue, SyntaxNode syntaxNode) { // Get reference to the YacksCompilation object (or null) YacksCompilation yacksCompilationOpt = ((CSharpCompilation) _module.CommonCompilation)._YacksCompilation; Debug.Assert(yacksCompilationOpt != null); // This is temporary - fails if modifying turned off // Determine if we are processing the constructor of a static object implementing a // disguised string int stringyNumber = 0; int shiftOrUnshift = 0; if (constantValue.Discriminator == ConstantValueTypeDiscriminator.String && constantValue.StringValue != null && constantValue.StringValue.Length == 0 && yacksCompilationOpt != null && GetStringyNumberIfRelevant(syntaxNode, yacksCompilationOpt, ref stringyNumber, ref shiftOrUnshift)) { // This syntax node represents the "" string in a static object constructor associated // with a disguised string. Disguise the string associated with the stringy number and // emit a ldstr opcode to load it. This results in the disguised string being added to // the #US (user string) "metadata stream" in the PE file. _builder.ProcessAssignmentInStaticClassConstructorRhs( YacksCore.M0002(yacksCompilationOpt.StringyNumberToString[stringyNumber - 1], -shiftOrUnshift), stringyNumber); return; } // Test if necessary to test for "logging token" syntactic units if (constantValue.Discriminator == ConstantValueTypeDiscriminator.Int32 && constantValue.Int32Value == 0 && syntaxNode.HasTrailingTrivia && yacksCompilationOpt != null && yacksCompilationOpt.ProcessLoggingTokens) { // Test if these are the syntactic units for a "logging token" SyntaxTriviaList triviaList = syntaxNode.GetFirstToken().TrailingTrivia; if (triviaList.Count == 2 && triviaList[0].Kind() == SyntaxKind.WhitespaceTrivia && triviaList[0].ToString() == " " && triviaList[1].Kind() == SyntaxKind.MultiLineCommentTrivia && triviaList[1].ToString() == "/*LogToken*/") { // These syntax nodes represents a log token, i.e., "0 /*LogToken*/". Get the line // number for the C# source code line, and the line number for the start of the C# // method enclosing the log token. Then record the line offset in the object // referenced by the _method field and emit a Ldc_i4 opcode and a placeholder token. int tokenLine = syntaxNode.Location.GetLineSpan().StartLinePosition.Line + 1; int methodLine = _method.Locations[0].GetLineSpan().StartLinePosition.Line + 1; _builder.ProcessLogTokenInSourceCode(_method, methodLine, tokenLine); return; } } // Standard processing for all constant values other than the logging tokens and the "" // strings in the static object constructors generated to implement undisguising of // disguised strings _builder.EmitConstantValue(constantValue); }

src\Compilers\Core\Portable\CodeGen\ILBuilderEmit.Yacks.cs

This is a source file which has been added to the CodeAnalysis project. It has also been previously listed in the same two blog articles mentioned above.

/// <summary> /// Method to record the line offset of the log token within the C# method in the object // referenced by the _method field and emit a Ldc_i4 opcode and a placeholder token. /// </summary> internal void ProcessLogTokenInSourceCode(IMethodDefinitionForYacks methodDefinition, int methodLine, int tokenLine) { // Test for first log token in this method, create List<> collections if so if (methodDefinition.LogTokenLineOffsets == null) { methodDefinition.LogTokenLineOffsets = new List<int>(); methodDefinition.MethodBodyIlOffsets = new List<int>(); } // Emit a Ldc_i4 opcode and the place-holder constant value 0x42424242 EmitOpCode(ILOpCode.Ldc_i4); int methodBodyIlOffset = this.GetCurrentWriter().Count; EmitInt32(YacksCompilation.CLogTokenPlaceholderI); // Record the necessary information for later processing in MetadataWriter methodDefinition.LogTokenLineOffsets.Add(tokenLine - methodLine); methodDefinition.MethodBodyIlOffsets.Add(methodBodyIlOffset); }

src\Compilers\Core\Portable\PEWriter\IMethodDefinitionForYacks.cs

This is a new source file which has been added to the CodeAnalysis project.

// Copyright (c) Merlinia A/S. All Rights Reserved. Licensed under the Apache License, Version 2.0. (Just to be compatible with the Microsoft Roslyn license.) using System.Collections.Generic; namespace Microsoft.CodeAnalysis.PEWriter { /// <summary> /// Interface used to pass information about possible logging tokens from the MethodSymbol class /// (which is in project CSharpCodeAnalysis) to the MetadataWriter class (which is in this /// CodeAnalysis project). This is used by code added by Yacks modifications that generate the /// logging tokens and emit them in the PE file and persist them in Yacks metadata. /// /// See comments in MethodSymbol.Yacks.cs in the CSharpCodeAnalysis project for more information. /// </summary> internal interface IMethodDefinitionForYacks { List<int> LogTokenLineOffsets { get; set; } List<int> MethodBodyIlOffsets { get; set; } } }

src\Compilers\CSharp\Portable\Symbols\MethodSymbol.Yacks.cs

This is a new source file which has been added to the CSharpCodeAnalysis project.

// Copyright (c) Merlinia A/S. All Rights Reserved. Licensed under the Apache License, Version 2.0. (Just to be compatible with the Microsoft Roslyn license.) using System.Collections.Generic; using Microsoft.CodeAnalysis.PEWriter; namespace Microsoft.CodeAnalysis.CSharp.Symbols { /// <summary> /// This source file adds fields (currently only two properties) to the MethodSymbol class that /// are used by the (modified) CodeGenerator class to record information about logging tokens /// that have been specified in the method. These fields are defined here instead of in one of /// the source files MethodSymbol.cs or MethodSymbolAdapter.cs to reduce the amount of /// modifications made to Roslyn source files. /// /// The current implementation of log tokens is minimal - it just notes line offset within the /// enclosing C# method. If desired this could be extended to record things such as the source /// line number for the method and the name of the source file containing the method. /// /// These fields should probably be placed in the SourceMethodSymbol, SourceMemberMethodSymbol or /// SourceOrdinaryMethodSymbol class instead, as the MethodSymbol class is probably too low in /// the inheritance hierarchy to be the optimal place. /// </summary> internal partial class MethodSymbol : IMethodDefinitionForYacks { // List<> of ints representing the number of lines from the start of the C# method to the line // (or lines) on which the log token (or log tokens) are located. For example for this code: // // static void Main() // { // Console.WriteLine("" + 0 /*LogToken*/); // } // // ... the List<> below will contain a single value = 2, while for this code: // // static void Main() { // Console.WriteLine("" + 0 /*LogToken*/); // Console.WriteLine("" + 0 /*LogToken*/); // } // // ... the List<> below will contain two values = 1 and 2. // // If the method contains no log tokens, or if the Yacks option to process logging tokens is // not turned on, then the value of this property remains null. public List<int> LogTokenLineOffsets { get; set; } = null; // List<> of ints that record the offset(s) into the method's IL body where the temporary // placeholder values 0x42424242 have been placed. (MetadataWriter will replace these // placeholder values with the log token values.) If the above field is null then this will // also be null. public List<int> MethodBodyIlOffsets { get; set; } } }

src\Compilers\Core\Portable\PEWriter\MetadataWriter.cs

This source file is in the CodeAnalysis project. It has been mentioned in many of the previous blog articles in this series - it's where many of my Roslyn modifications are based.

private int[] SerializeMethodBodies(BlobBuilder ilBuilder, PdbWriter nativePdbWriterOpt, out Blob mvidStringFixup) { ... if (method.HasBody()) { body = method.GetBody(Context); if (body != null) { //Yacks14: Generate log tokens if necessary and prepare to emit them PrepareToProcessLogTokensInMethod(method as IMethodDefinitionForYacks); ... }

private void WriteInstructions(Blob finalIL, ImmutableArray<byte> generatedIL, ref UserStringHandle mvidStringHandle, ref Blob mvidStringFixup) { ... case OperandType.InlineSig: // calli case OperandType.InlineBrTarget: case OperandType.InlineI: case OperandType.ShortInlineR: //Yacks14: Process patching the placeholder for a log token if relevant ProcessPossibleLogToken(writer, offset); offset += 4; break; ... }

src\Compilers\Core\Portable\PEWriter\MetadataWriter.Yacks1.cs

This is a source file which has been added to the CodeAnalysis project, along with one called MetadataWriter.Yacks2.cs. (It used to be a single source file, but as soon as it got larger than 1000 lines of C# code I felt an urge to divide it into two source files - my mind clouds over when having to work with large source files.)

/// <summary> /// Method called before MetadataWriter serializes a method body. This generates log tokens if /// necessary and prepares to emit them by saving a reference to the method definition object /// and resetting an index used for processing multiple log tokens in the method. /// </summary> private void PrepareToProcessLogTokensInMethod( IMethodDefinitionForYacks methodDefinitionForYacks) { Debug.Assert(methodDefinitionForYacks != null); // Test if the method contained any log tokens (and Yacks option to process log tokens is // turned on) _methodDefinition = methodDefinitionForYacks; if (methodDefinitionForYacks.MethodBodyIlOffsets == null) return; // Initialize work fields _indexForNextLogToken = 0; _logTokenValues = new List<int>(methodDefinitionForYacks.MethodBodyIlOffsets.Count); // Prepare for following processing ITypeDefinitionMember typeDefinitionMember = methodDefinitionForYacks as ITypeDefinitionMember; IMethodDefinition methodDefinition = methodDefinitionForYacks as IMethodDefinition; YacksCompilation yacksCompilation = module.CommonCompilation._YacksCompilation; Debug.Assert(typeDefinitionMember != null && methodDefinition != null && yacksCompilation != null); // Find or create a Yacks metadata object for the type containing the C# method containing // the log token YacksTypeInfo typeInfo = yacksCompilation.FindOrCreateTypeInfo(FullyQualifiedTypeName( typeDefinitionMember.ContainingTypeDefinition as INamedTypeDefinition)); // Find or create a Yacks metadata object for the C# method containing the log token YacksMethodInfo methodInfo = yacksCompilation.FindOrCreateMethodInfo(typeInfo, methodDefinition.Name, GetMethodSignatureAsString(methodDefinition)); // Obtain the previously-created log token numbers and/or create new log token numbers methodInfo.CreateLogTokenListIfNecessary(); bool updateNeeded = methodInfo.LogTokens.Count < methodDefinitionForYacks.LogTokenLineOffsets.Count; for (int i = 0; i < methodDefinitionForYacks.LogTokenLineOffsets.Count; i++) { if (i >= methodInfo.LogTokens.Count) methodInfo.LogTokens.Add(yacksCompilation.GetNextLogToken()); _logTokenValues.Add(methodInfo.LogTokens[i]); } if (updateNeeded) yacksCompilation.UpdateProjectInfo(); } /// <summary> /// Method called when MetadataWriter has emitted a Ldc_i4 opcode (among others) and is now /// doing a scan of the emitted IL. This detects if the four bytes following the Ldc_i4 is a /// log token placeholder, and replaces it with the correct log token value if so. /// </summary> private void ProcessPossibleLogToken(BlobWriter blobWriter, int localOffset) { // Test if there are log tokens in the method being emitted, and if the IL being scanned is // the load of the next log token (actually log token placeholder) if (_methodDefinition?.MethodBodyIlOffsets == null || _indexForNextLogToken >= _methodDefinition.MethodBodyIlOffsets.Count || localOffset < _methodDefinition.MethodBodyIlOffsets[_indexForNextLogToken]) return; // Check that the IL data that has been emitted is as expected (a log token placeholder) byte[] toTest = blobWriter.ToArray(localOffset, 4); Debug.Assert(toTest[0] == YacksCompilation.CLogTokenPlaceholderB && toTest[1] == YacksCompilation.CLogTokenPlaceholderB && toTest[2] == YacksCompilation.CLogTokenPlaceholderB && toTest[3] == YacksCompilation.CLogTokenPlaceholderB); // Replace the placeholder with the correct log token value and prepare for processing the // next log token (if any) blobWriter.Offset = localOffset; blobWriter.WriteInt32(_logTokenValues[_indexForNextLogToken]); _indexForNextLogToken++; }

A quick demonstration

There is more code that I've added to Roslyn to implement the logging tokens, and if you really want to study it you can download my Roslyn modifications, as specified here.

Here's a tiny sample program that I used when testing the logging tokens facility:

using System; namespace TestLogTokens { class Program { static void Main() { Console.WriteLine("This is a Yacks log token: " + 0 /*LogToken*/); Console.WriteLine("This is another Yacks log token: " + 0 /*LogToken*/); Console.ReadKey(); // So above output can be viewed and admired } } }

Compiling the above with my modified Roslyn compiler, and then running the resulting program produces this output:

ModRos 14 Snap2

The value 99 is due to me having played around with the Yacks Metadata Editor program. And speaking of the Metadata Editor program, here's how the log tokens are displayed there:

ModRos 14 Snap3

ModRos 14 Snap4

You must login to post a comment.
Loading comment... The comment will be refreshed after 00:00.

Be the first to comment.