Common.Logging over log4Net and event specific properties preserved in async code

There's an unfortunate issue in between the Common.Logging and log4Net we've stumbled upon.

The problem is related to so called event specific properties, additional values that should be logged and are usually added per log call. In the pattern layout, these additional properties are specified using the %P, e.g.

<layout type="log4net.Layout.PatternLayout">
	<conversionPattern value="%newline%date [%thread] [%P{vFoo} %P{vBar}] %-5level - %message" />
</layout>

In the above example, the two additional properties, vFoo and vBar are injected into the logger and their values are part of the log entries.

If log4net is used directly, you just set your properties, either in a global context (properties set once and shared), in a thread context or a logical thread context

ILog logger = LogManager.GetLogger( typeof( Program ) );

// shared
GlobalContext.Properties["vFoo"] = 5;
GlobalContext.Properties["vBar"] = 5;

// per thread (doesn't work with async/await)
ThreadContext.Properties["vFoo"] = 5;
ThreadContext.Properties["vBar"] = 5;

// per logical thread (works correctly over async/await)
LogicalThreadContext.Properties["vFoo"] = 5;
LogicalThreadContext.Properties["vBar"] = 5;

The distinction between the last two is a strict motivation to write this entry. Note that putting properties in a thread context (implemented with log4net using ThreadStatic) could be useful in some scenarios but doesn't support async/await, mainly, when the continuation runs in a different thread, properties are lost. That's what the logical thread context does, it's implemented using the CallContext and properties are properly preserved in async/await code.

Now, move to Common.Logging which is commonly used as a wrapper over specific loggers. Common.Logging logger supports global variables context and thread variables context:

var log = LogManager.GetLogger( typeof( Program ) );

// shared
log.GlobalVariablesContext.Set( "vFoo", 5 );
log.GlobalVariablesContext.Set( "vBar", 5 );

// per thread
log.ThreadVariablesContext.Set( "vFoo", 5 );
log.ThreadVariablesContext.Set( "vBar", 5 );

And where's the logical thread context?

Nowhere, it's missing from Common.Logging. Namely ...

var log = LogManager.GetLogger( typeof( Program ) );

log.ThreadVariablesContext.Set( "vFoo", 5 );
log.ThreadVariablesContext.Set( "vBar", 5 );

log.Debug( "foo bar hello" );

await Task.Delay( 1 );

log.Debug( "foo bar hello 2" );

await Task.Delay( 1 );

log.Debug( "foo bar hello 3" );

... will log both variables correctly only the first time and will log (null) in two subsequent calls.

Problem here is that log4net is supposed to search for variables set only using one it's own three classes presented earlier, GlobalContext, ThreadContext or the LogicalThreadContext. And when Common.Logging is used throughout the application stack, there's no way to call any of the three directly.

Our approach was to create a proxy logger and replace the log manager factory with one that returns the proxy logger. The proxy logger would reimplement the ThreadVariablesContext to use the other way of storing thread variables.

Let's start with the factory. It's supposed to be defined down the stack, so that it can be used everywhere. Since it can't use log4net directly, we'll use the common pattern to make the context factory injectable from within the Composition Root

public class VLogManager
{
	static Func<IVariablesContext> _variablesContextFactory;

	public static void SetVariablesContextFactory( Func<IVariablesContext> variablesContextFactory )
	{
		_variablesContextFactory = variablesContextFactory;                
	}

	public static ILog GetLogger( Type t )
	{
		return new WrappedLogger( LogManager.GetLogger( t ), _variablesContextFactory() );
	}
}

Now comes the proxy logger, defined somewhere near the custom log manager. The logger is not supposed to use log4net, too

public class WrappedLogger : ILog
{
	private ILog _log;

	private IVariablesContext _logicalThreadVariablesContext;

	public WrappedLogger( ILog log, IVariablesContext localVariablesContext )
	{
		this._log                           = log;
		this._logicalThreadVariablesContext = localVariablesContext;
	}

	public bool IsTraceEnabled { get => _log.IsTraceEnabled; }
	public bool IsDebugEnabled { get => _log.IsDebugEnabled; }
	public bool IsErrorEnabled { get => _log.IsErrorEnabled; }
	public bool IsFatalEnabled { get => _log.IsFatalEnabled; }
	public bool IsInfoEnabled { get => _log.IsInfoEnabled; }
	public bool IsWarnEnabled { get => _log.IsWarnEnabled; }
	public IVariablesContext GlobalVariablesContext { get => _log.GlobalVariablesContext; }
	public IVariablesContext ThreadVariablesContext { get => this._logicalThreadVariablesContext; }
	public INestedVariablesContext NestedThreadVariablesContext { get => _log.NestedThreadVariablesContext; }

	public void Debug( object message )
	{
		_log.Debug( message );
	}

	public void Debug( object message, Exception exception )
	{
		_log.Debug( message, exception );
	}

	public void Debug( Action<FormatMessageHandler> formatMessageCallback )
	{
		_log.Debug( formatMessageCallback );
	}

	public void Debug( Action<FormatMessageHandler> formatMessageCallback, Exception exception )
	{
		_log.Debug( formatMessageCallback, exception );
	}

	public void Debug( IFormatProvider formatProvider, Action<FormatMessageHandler> formatMessageCallback )
	{
		_log.Debug( formatProvider, formatMessageCallback );
	}

	public void Debug( IFormatProvider formatProvider, Action<FormatMessageHandler> formatMessageCallback, Exception exception )
	{
		_log.Debug( formatProvider, formatMessageCallback, exception );
	}

	public void DebugFormat( string format, params object[] args )
	{
		_log.DebugFormat( format, args );
	}

	public void DebugFormat( string format, Exception exception, params object[] args )
	{
		_log.DebugFormat( format, exception, args );
	}

	public void DebugFormat( IFormatProvider formatProvider, string format, params object[] args )
	{
		_log.DebugFormat( formatProvider, format, args );
	}

	public void DebugFormat( IFormatProvider formatProvider, string format, Exception exception, params object[] args )
	{
		_log.DebugFormat( formatProvider, format, exception, args );
	}

	public void Error( object message )
	{
		_log.Error( message );
	}

	public void Error( object message, Exception exception )
	{
		_log.Error( message, exception );
	}

	public void Error( Action<FormatMessageHandler> formatMessageCallback )
	{
		_log.Error( formatMessageCallback );
	}

	public void Error( Action<FormatMessageHandler> formatMessageCallback, Exception exception )
	{
		_log.Error( formatMessageCallback, exception );
	}

	public void Error( IFormatProvider formatProvider, Action<FormatMessageHandler> formatMessageCallback )
	{
		_log.Error( formatProvider, formatMessageCallback );
	}

	public void Error( IFormatProvider formatProvider, Action<FormatMessageHandler> formatMessageCallback, Exception exception )
	{
		_log.Error( formatProvider, formatMessageCallback, exception );
	}

	public void ErrorFormat( string format, params object[] args )
	{
		_log.ErrorFormat( format, args );
	}

	public void ErrorFormat( string format, Exception exception, params object[] args )
	{
		_log.ErrorFormat( format, exception, args );
	}

	public void ErrorFormat( IFormatProvider formatProvider, string format, params object[] args )
	{
		_log.ErrorFormat( formatProvider, format, args );
	}

	public void ErrorFormat( IFormatProvider formatProvider, string format, Exception exception, params object[] args )
	{
		_log.ErrorFormat( formatProvider, format, exception, args );
	}

	public void Fatal( object message )
	{
		_log.Fatal( message );
	}

	public void Fatal( object message, Exception exception )
	{
		_log.Fatal( message, exception );
	}

	public void Fatal( Action<FormatMessageHandler> formatMessageCallback )
	{
		_log.Fatal( formatMessageCallback );
	}

	public void Fatal( Action<FormatMessageHandler> formatMessageCallback, Exception exception )
	{
		_log.Fatal( formatMessageCallback, exception );
	}

	public void Fatal( IFormatProvider formatProvider, Action<FormatMessageHandler> formatMessageCallback )
	{
		_log.Fatal( formatProvider, formatMessageCallback );
	}

	public void Fatal( IFormatProvider formatProvider, Action<FormatMessageHandler> formatMessageCallback, Exception exception )
	{
		_log.Fatal( formatProvider, formatMessageCallback, exception );
	}

	public void FatalFormat( string format, params object[] args )
	{
		_log.FatalFormat( format, args );
	}

	public void FatalFormat( string format, Exception exception, params object[] args )
	{
		_log.FatalFormat( format, exception, args );
	}

	public void FatalFormat( IFormatProvider formatProvider, string format, params object[] args )
	{
		_log.FatalFormat( formatProvider, format, args );
	}

	public void FatalFormat( IFormatProvider formatProvider, string format, Exception exception, params object[] args )
	{
		_log.FatalFormat( formatProvider, format, exception, args );
	}

	public void Info( object message )
	{
		_log.Info( message );
	}

	public void Info( object message, Exception exception )
	{
		_log.Info( message, exception );
	}

	public void Info( Action<FormatMessageHandler> formatMessageCallback )
	{
		_log.Info( formatMessageCallback );
	}

	public void Info( Action<FormatMessageHandler> formatMessageCallback, Exception exception )
	{
		_log.Info( formatMessageCallback, exception );
	}

	public void Info( IFormatProvider formatProvider, Action<FormatMessageHandler> formatMessageCallback )
	{
		_log.Info( formatProvider, formatMessageCallback );
	}

	public void Info( IFormatProvider formatProvider, Action<FormatMessageHandler> formatMessageCallback, Exception exception )
	{
		_log.Info( formatProvider, formatMessageCallback, exception );
	}

	public void InfoFormat( string format, params object[] args )
	{
		_log.InfoFormat( format, args );
	}

	public void InfoFormat( string format, Exception exception, params object[] args )
	{
		_log.InfoFormat( format, exception, args );
	}

	public void InfoFormat( IFormatProvider formatProvider, string format, params object[] args )
	{
		_log.InfoFormat( formatProvider, format, args );
	}

	public void InfoFormat( IFormatProvider formatProvider, string format, Exception exception, params object[] args )
	{
		_log.InfoFormat( formatProvider, format, exception, args );
	}

	public void Trace( object message )
	{
		_log.Trace( message );
	}

	public void Trace( object message, Exception exception )
	{
		_log.Trace( message, exception );
	}

	public void Trace( Action<FormatMessageHandler> formatMessageCallback )
	{
		_log.Trace( formatMessageCallback );
	}

	public void Trace( Action<FormatMessageHandler> formatMessageCallback, Exception exception )
	{
		_log.Trace( formatMessageCallback, exception );
	}

	public void Trace( IFormatProvider formatProvider, Action<FormatMessageHandler> formatMessageCallback )
	{
		_log.Trace( formatProvider, formatMessageCallback );
	}

	public void Trace( IFormatProvider formatProvider, Action<FormatMessageHandler> formatMessageCallback, Exception exception )
	{
		_log.Trace( formatProvider, formatMessageCallback, exception );
	}

	public void TraceFormat( string format, params object[] args )
	{
		_log.TraceFormat( format, args );
	}

	public void TraceFormat( string format, Exception exception, params object[] args )
	{
		_log.TraceFormat( format, exception, args );
	}

	public void TraceFormat( IFormatProvider formatProvider, string format, params object[] args )
	{
		_log.TraceFormat( formatProvider, format, args );
	}

	public void TraceFormat( IFormatProvider formatProvider, string format, Exception exception, params object[] args )
	{
		_log.TraceFormat( formatProvider, format, exception, args );
	}

	public void Warn( object message )
	{
		_log.Warn( message );
	}

	public void Warn( object message, Exception exception )
	{
		_log.Warn( message, exception );
	}

	public void Warn( Action<FormatMessageHandler> formatMessageCallback )
	{
		_log.Warn( formatMessageCallback );
	}

	public void Warn( Action<FormatMessageHandler> formatMessageCallback, Exception exception )
	{
		_log.Warn( formatMessageCallback, exception );
	}

	public void Warn( IFormatProvider formatProvider, Action<FormatMessageHandler> formatMessageCallback )
	{
		_log.Warn( formatProvider, formatMessageCallback );
	}

	public void Warn( IFormatProvider formatProvider, Action<FormatMessageHandler> formatMessageCallback, Exception exception )
	{
		_log.Warn( formatProvider, formatMessageCallback, exception );
	}

	public void WarnFormat( string format, params object[] args )
	{
		_log.WarnFormat( format, args );
	}

	public void WarnFormat( string format, Exception exception, params object[] args )
	{
		_log.WarnFormat( format, exception, args );
	}

	public void WarnFormat( IFormatProvider formatProvider, string format, params object[] args )
	{
		_log.WarnFormat( formatProvider, format, args );
	}

	public void WarnFormat( IFormatProvider formatProvider, string format, Exception exception, params object[] args )
	{
		_log.WarnFormat( formatProvider, format, exception, args );
	}
}

Note how boring the proxy is, it merely delegates everything to the logger it wraps. The only part that is reimplemented is the ThreadVariablesContext.

public IVariablesContext ThreadVariablesContext { get => this._logicalThreadVariablesContext; }

Now, let's move to the Composition Root of the application stack, the place close to Main or Application_Start, where all references are available. This is where the variables context implementation can be provided

public class LogicalThreadVariablesContext : IVariablesContext
{
	public void Set( string key, object value )
	{
		LogicalThreadContext.Properties[key] = value;
	}

	public object Get( string key )
	{
		return LogicalThreadContext.Properties[key];
	}

	public bool Contains( string key )
	{
		return LogicalThreadContext.Properties[key] != null;
	}

	public void Remove( string key )
	{
		LogicalThreadContext.Properties.Remove( key );
	}

	public void Clear()
	{
		LogicalThreadContext.Properties.Clear();
	}
}

Note that this is where we are allowed to reference log4net! And the last piece - inject this class into the custom logger factory. Specifically, add this to Main or Application_Start

VLogManager.SetVariablesContextFactory( () => new LogicalThreadVariablesContext() );

This is it. Now, anywhere in your application stack you can inject custom variables into the logger ...

var log = VLogManager.GetLogger( typeof( Program ) );

log.ThreadVariablesContext.Set( "vFoo", 5 );
log.ThreadVariablesContext.Set( "vBar", 5 );

log.Debug( "foo bar hello" );

await Task.Delay( 1 );

log.Debug( "foo bar hello 2" );

await Task.Delay( 1 );

log.Debug( "foo bar hello 3" );

... and values are properly stored in the log. Note that the only change in client's code is the usage of the newly introduced log manager (VLogManager instead of the provided LogManager).

TypeScript puzzle No.2 (easy)

Consider following code

class Foo {
  bar() {
    return 1
  }
}

const foo = new Foo
foo.bar()

Now consider that for some reason we want to include a type assertion, rather than just foo we want foo as Foo.

class Foo {
  bar() {
    return 1
  }
}

const foo = new Foo
(foo as Foo).bar()

Surprisingly, this one doesn't compile, the error points to the last line and says

Block-scoped variable 'foo' used before its declaration

As always, your goal is to explain the unexpected behavior here.

TypeScript's Conditional Type Operator example

We all like good examples, examples which, when seen, make us grasp new ideas easier. I believe the notion of Conditional Types in TypeScript is often demonstrated in a way that makes you wonder what's the real purpose of it. Let's just have yet another example that could be useful here.

Let's start with a function type, it could be a type of a custom function or a built in function.

// a custom function
function foo( s: string, n: number, b: boolean | symbol) : void {

}
type FooType = typeof foo;
// FooType = (s: string, n: number, b: boolean | symbol) => void

// the built in function, Array.prototype.slice
type ArraySliceType = typeof Array['prototype']['slice'];
// ArraySliceType = (start?: number | undefined, end?: number | undefined) => any[]

The two function types have a different number of parameters but with the TypeScript's type system, we can write an auxiliary type that just picks a type of specific parameter.

This is where the actual example begins. The initial part of the example is based on a code presented in Programming TypeScript by B. Cherny. Let's start with a type that picks a parameter that comes, like, second on the list of parameters.

type SecondArg<F> = F extends (a: any, b: infer B, ...c: any ) => any ? B : never;

Let's comment that. The SecondArg type is a generic type that expects a single generic parameter, F. This single generic parameter type is checked to be a function (the F extends ... part) and depending on the test, the conditional operator either returns an inferred type of the second argument (infer B) or fails (never).

Let's test this

type SecondArgString = SecondArg<string>;
// never
type SecondArgFoo = SecondArg<FooType>;
// number
type SecondArgArraySlice = SecondArg<ArraySliceType>;
// number | undefined

This works great and to me - it's enough to demonstrate how useful the ? : conditional operator is. Using this technique we can pick a type of a specific argument of specific function type, which, as far as I know, is not possible in languages like, say, C# or Java. In C#, if there's a function and the second argument of the function is, say, int and you have to declare a variable of this type, you have to know this type in advance to even start writing code.

But, this example can easily be pushed forward, why just pick a specific, second parameter? Why not write a generic type that picks the argument we want, first, second, third? Let's go beyond the original example from the book.

The question is, can numbers (parameter indexes) can be arguments of generic types?

The answer is, sure, it's TypeScript, literals can be types. Remember the part of the TypeScript tutorial when you learn that a string 'foo' can also be a type that is just a subtype of string? Well, 5 can be a type that's just a subtype of number.

The only small technical issue is that our new generic type needs two generic arguments and we need constraints on both of them which the ? : operator doesn't support directly (or I don't know how to do it :).

The first approach involves nesting the ? : operator so that the nested part introduces the constraint on the second argument.

type NThArg<F, N> = 
    F extends (...c: infer C) => any 
    ? (N extends number ? C[N] : never ) 
    : never;  
  

Please take a while to compare this new type to the previous one. As you can see, the parameter list is expressed in a more concise way, we don't need to introduce specific parameters, instead we hide them all under the spread (...) operator. But the other generic parameter, N is constrained to be a number (the N extends a number part) so that it can be used to just index the signature type (the C[N]) part.

If nesting the conditional type operator bothers you as much as it bothers me, there's another version

type NThArg2<F, N extends number> = 
    F extends (...c: infer C) => any 
    ? C[N]
    : never;  
  

This time there's no nesting of the conditional operator. Instead, the constraint on N is expressed directly in type signature which works here as the constraint on N doesn't really invole anything fancy (no need for conditionals, infer, etc.)

Both operators work, please take your time to play around

type FooTypeNth10  = NThArg<FooType, 0>
// string
type FooTypeNth11  = NThArg<FooType, 1>
// number
type NThArgSlice = NThArg<ArraySliceType, 1>;
// number | undefined

type FooTypeNth2  = NThArg2<FooType, 1>
// number
type NThArgSlice2 = NThArg2<ArraySliceType, 1>;
// number | undefined  
  

And just by the way, did you know that TypeScript's type system is Turing Complete (please also take a look here and here and here)? This basically means that we could write actual programs using types only and results would be computed by the compiler during compilation. Please check the linked article to find few possible ways this could be used (and no, it's not quite useful, you wouldn't like to write code that runs on your type system).

Happy coding.

Node.js + Express + TypeScript (ts-node reloaded)

This is a short follow up to one of my previous posts, the Node.js + Express + TypeScript where a tiny tutorial on writing node.js node with TypeScript was discussed.

This time I'd like to introduce the ts-node which basically wraps the TypeScript execution in a single pipeline so that there's no need to precompile the TypeScript to JavaScript.

One of ways to use the ts-node is to install it globally and run the TypeScript code with

ts-node app.ts

Note only that the tsconfig.json has to be present, just to configure TypeScript options.

However, to also be able to debug the TypeScript from the Visual Studio Code and still use the ts-node to execute the code, install the ts-node locally and create a .vscode/launch.json section

{
    "name": "ts-node",
    "type": "node",
    "request": "launch",
    "args": ["${workspaceFolder}\\app.ts"],
    "runtimeArgs": ["-r", "ts-node/register"],
    "cwd": "${workspaceRoot}",
}

A tiny code to test this

// app.ts
import * as http from 'http';
import express, { Express, Request, Response } from 'express';

var app: Express = express();

app.get('/', (req: Request, res: Response) => {
    res.write('hello world');
    res.end();
});

var server = http.createServer(app)

server.listen(3000);

console.log( 'started' );

Cannot navigate to the symbol under the carret after updating VS 2022

After VS 2022 has been updated, suddenly some projects refuse to provide navigation between tokens, you can't just click on anything and "Go to Definition..."

There are couple of suggested workarounds, including restarting VS, deleting *.user files or going to Options/Debugging/Symbols and invoking Empty symbol cache

A working solution has been found here and it consists in updating the Microsoft.Net.Compilers package referenced in affected projects to a newer version.

This however, potentially causes another issue, this time on a build server, if you happen to rely on msbuild. This time, the MSB4184 is thrown

error MSB4184: The expression ""App_Start\RouteConfig.cs".GetPathsOfAllDirectoriesAbove()" 
cannot be evaluated. Method 'System.String.GetPathsOfAllDirectoriesAbove' not found

Turns out, this also has been observed. The proposed solution is to uninstall the Microsoft.Net.Compilers, this breaks token resolution is VS, though.

What seems to work for us is to have

• Microsoft.Net.Compilers 2.10
• Microsoft.CodeDom.Providers.DotNetCompilerPlatform 3.60

Visual Studio 2022, Environment/Startup

What happens when you just open the Visual Studio? It displays a solution selector where you pick up one of latests solutions. This is the default behavior. This can be changed, if you go to Options and then go to Environment/Startup page, you can change this to just show an empty environment.

People got used to it, also, it's mentioned in the documentation

The only problem is that the Environment/Startup is not there in Visual Studio 2022.

Instead, it's been moved to Environment/General, unfortunately, it's at the very bottom of the page and can easily be missed because you need to actually scroll down the page to see it

Node.js + Express + TypeScript

The Node.js + Express + Javascript is a great platform and this short tutorial shows how to add TypeScript to the picture.

Start with installing TypeScript compiler globally

npm install typescript -g

so that whenever you invoke tsc from the command line, the compiler follows your tsconfig.json and does its job. Then add the tsconfig.json

{
    "compilerOptions": {
        "lib": [
            "es2021", "DOM"
        ],
        "module": "commonjs",
        "target": "es2021",
        "strict": true,
        "esModuleInterop": true,
        "sourceMap": true                
    }
}

Note that we specifically ask the module subsystem to translate TypeScript's export/imports into node.js commonjs modules. We also turn on the esModuleInterop flag for better node.js compatibility.

Now install some typings for node and express (other typings should possibly also be installed, depending on what packages you are going to use.

npm i --save-dev @types/node
npm i --save-dev @types/express

Create the app.ts file, which will be the starting point of the app and add .vscode/launch.json with

{
    "version": "0.2.0",
    "configurations": [
        {
            "type": "pwa-node",
            "request": "launch",
            "name": "Launch Program",
            "skipFiles": [
                "<node_internals>/**"
            ],
            "program": "${workspaceFolder}\\app.ts",
            "outFiles": [
                "${workspaceFolder}/**/*.js"
            ]
        }
    ]
}

Note how the entry point (program) is set up here. Because the Typescript compiler will generate source maps, you would be able to run&debug the Typescript code.

Writing Typescript is easy now. Create an example express app

import * as http from 'http';
import express from 'express';

var app = express();

app.get('/', (req, res) => {
    res.write('hello world');
    res.end();
});

var server = http.createServer(app)

server.listen(3000);

console.log( 'started' );

Note how express is imported and how a library module (http) is imported - in both cases, there's the full intellisense support in VS Code as well as the support from the Typescript compiler.

To compile the code just invoke

tsc

once. To run the compiler in the watch mode:

tsc --watch

To show how TS modules work, create a simple module, m.ts with

class Example {
    DoWork( s: string ) : string {
        return s + ' from Example';
    }
}

export default Example;

and import it in the app.ts

import * as http from 'http';
import express from 'express';
import Example from './m';

var app = express();

app.get('/', (req, res) => {

    let e = new Example();

    res.write(e.DoWork('hello world'));
    res.end();
});

var server = http.createServer(app)

server.listen(3000);

console.log( 'started' );

Note how m.ts is compiled to m.js and also note how m.js is imported in the app.js (compiled from app.ts).