AmbiguousMatchException on a simple NET.Core Minimal API

One of my students pointed out to an unexpected issue in a simple .NET.Core app using the Minimal API

var builder = WebApplication.CreateBuilder(args);
var app = builder.Build();

app.MapGet("/", () => "Hello World!");

app.MapGet("/{param}", (string param) =>
{
    return $"Parametr: {param}";
});

app.MapGet("/{param:int}", (int param) =>
{
    return $"Parametr typu int: {param}";
});

app.MapGet("/{param:length(1,10)}", (string param) =>
{
    return $"Parametr z ograniczeniem długości: {param}";
});

app.MapGet("/{param:required}", (string param) =>
{
    return $"Parametr wymagany: {param}";
});

app.MapGet("/{param:regex(^\\d{{4}}$)}", (string param) =>
{
    return $"Parametr spełniający wyrażenie regularne: {param}";
});

app.Run();

The problem here is that routes overlap and it's not easily discoverable until a runtime exception is thrown when you try to navigate to a path that is matched by multiple endpoints. The AmbiguousMatchException is thrown.

My first attempt to workaround this was to wrap routes with UseRouting / UseEndpoints, hoping that this makes routing explicit. However, a closer look at the documentation reveals that

URL matching operates in a configurable set of phases. In each phase, the output is a set of matches. The set of matches can be narrowed down further by the next phase. The routing implementation does not guarantee a processing order for matching endpoints. All possible matches are processed at once. The URL matching phases occur in the following order.

and also

there are other matches with the same priority as the best match, an ambiguous match exception is thrown.

This is kind of complicated to people coming with .NET.Framework background where even if routes overlap, a first matching route is picked up and its handler is executed. The .NET.Core introduces the idea of priorities in routes, clearly covered by the documentation. In case there are multiple routes with the same priority, we have an exception.

Fortunately enough, the docs also give at least one hint on what to do - a custom EndpointSelector can be used. A custom selector could just replace the DefaultEndpointSelector that is normally registered in the service container, the default selector is useless as it's internal and its method is not virtual. But the custom selector is just a few lines of code.

using Microsoft.AspNetCore.Routing.Matching;
using System.Text.Json;
 
var builder = WebApplication.CreateBuilder(args);
builder.Services.AddSingleton<EndpointSelector, CustomEndpointSelector>();
var app = builder.Build();
 
app.UseRouting();
 
app.MapGet( "/", () => "Hello World!" );
 
app.MapGet( "/{param}", ( string param ) =>
{
    return $"Parametr: {param}";
} );
 
app.MapGet( "/{param:int}", ( int param ) =>
{
    return $"Parametr typu int: {param}";
} );
 
app.MapGet( "/{param:length(1,10)}", ( string param ) =>
{
    return $"Parametr z ograniczeniem długości: {param}";
} );
 
app.MapGet( "/{param:required}", ( string param ) =>
{
    return $"Parametr wymagany: {param}";
} );
 
app.MapGet( "/{param:regex(^\\d{{4}}$)}", ( string param ) =>
{
    return $"Parametr spełniający wyrażenie regularne: {param}";
} );
 
 
app.UseEndpoints( (endpoints) => { } );
 
app.Run();
 
class CustomEndpointSelector : EndpointSelector
{
    public override async Task SelectAsync( HttpContext httpContext, CandidateSet candidates )
    {
        CandidateState selectedCandidate = new CandidateState();
 
        for ( var i=0; i < candidates.Count; i++ )
        {
            if ( candidates.IsValidCandidate( i ) )
            {
                selectedCandidate = candidates[i];
                break;
            }
        }
 
        httpContext.SetEndpoint( selectedCandidate.Endpoint );
        httpContext.Request.RouteValues = selectedCandidate.Values;
    }
}

Please use this as a starting point to build a more sophisticated approach, fulfilling any specific requirements.

Fido2.NetFramework

Just published a working code of a port of the fido2-net-lib library. The library is great, it works but there's a drawback - it targets .NET 6 (or higher) which means that creating Fido2/Webauthn compatible website in .NET 4.X using the library is impossible.

My ported library, called the Fido2.NetFramework is supposed to fill the gap. I downgraded the code so that it compiles using the old C# 4.8 compiler, I replaced all external references that targets APIs/libraries/frameworks that are not available in .NET 4.8. For example, the Nsec.Cryptography used in the source library, was replaced with BouncyCastle.

The code contains a working demo.

There's still some work to do, in particular, validate the port by porting unit tests and creating extra compatibility tests.

Rust/WebAssembly vs Javascript performance on Mandelbrot animation rendering

The pending question Is Rust/Wasm fast enough to even bother when comparing to Javascript? has now yet another biased benchmark. I've decided to take one of my Julia/Mandelbrot demos, benchmark it "as-is" and then, port to Rust and compare.

The HTML/Javascript source is short enough to post it here, the original demo code has some additional features (zooming) which are not present here

<!DOCTYPE html>
<html lang="en">
<head>
    <meta charset="UTF-8">
    <title>Mandelbrot</title>
	<script type="text/javascript">
	        
        var cx = 0, cy = 0, kat1 = 0, kat2 = 1;           
        
        var WJulia = 1024;
        var HJulia = 1024;
        var frame  = 0;
        var startDate;
    
        var contextJulia;
        var contextSmall;
        var pixJulia;
        var imgdJulia;

        var iStart;
        var iEnd;
        var jStart;
        var jEnd;

        var iDelta;
        var jDelta;
        
        function setInitialScale()
        {
            iStart = -1.92;
            iEnd   = 1.92;
            jStart = -1.92;
            jEnd   = 1.92;

            iDelta = (iEnd-iStart)/1024;
            jDelta = (jEnd-jStart)/1024;

            startDate = new Date();
        }

        function SetupMandel()
        {	 
            var elemJulia = document.getElementById('JuliaCanvas');
            if (elemJulia && elemJulia.getContext)
            {
                contextJulia = elemJulia.getContext('2d');
                if (contextJulia)
                {
                    imgdJulia = contextJulia.createImageData(WJulia, HJulia);         
                    pixJulia = imgdJulia.data;
                }
            }

            setInitialScale();
          
            /* start */
            requestAnimationFrame( LoopMandel );
        }
                         
        function LoopMandel()
        {	 
            kat1 += 0.0021;
            kat2 += 0.0039;
            cx = .681 * Math.sin(kat1);
            cy = .626 * Math.cos(kat2);

            frame++;
            document.getElementById('fps').innerHTML = `FPS: ${1000*frame/(new Date()-startDate)}`;
			
            RysujMandel();	 
            
            requestAnimationFrame( LoopMandel );
        }
         
         
        /* tworzenie bitowego obrazu */
        function RysujMandel()
        {
            /* obliczenia */
            var wi, wj;
            var i, j;

            var iterations = 255;

            var px = 0;
            for (i = iStart, wi = 0; wi < 1024; i += iDelta, wi++)
            {
                var py = 0;
                for (j = jStart, wj = 0; wj < 1024; j += jDelta, wj++)
                {
                    var c = 0;

                    var x = cx;
                    var y = cy;
         
                    while (((x*x + y*y) < 4) && (c < iterations))
                    {
                        [x, y] = [x * x - y * y + i, 2 * x * y + j];
                        c++;
                    }

                    SetPixelColor( pixJulia, (py * WJulia + px) << 2, 255, 255-c, 255-c, 255 - (c/2) );
                                        
                    py++;
                }
         
                px++;
            }
            
            /* kopiowanie bitowego obrazu do context/canvas */
            contextJulia.putImageData(imgdJulia, 0, 0);		 
        }
         
        function SetPixelColor(pix,offs, a, r, g, b)
        {            
            pix[offs++] = r;
            pix[offs++] = g;
            pix[offs++] = b;
            pix[offs] = a;
        }
         
        window.addEventListener( 'load', SetupMandel );
        
        </script>    
</head>
<body>
    <span id="fps" style='display:block'></span>
    <canvas id="JuliaCanvas" width="1024" height="1024">
	</canvas>
</body>
</html>

When run on my machine and the Edge Browser, it makes ~10-11 frames per second. Not bad assuming 1024x1024 image and 255 iterations.

Same code ported to Rust and compiled with wasm-pack

// https://rustwasm.github.io/wasm-bindgen/examples/dom.html
use wasm_bindgen::prelude::*;
use wasm_bindgen::Clamped;
use web_sys::{CanvasRenderingContext2d, ImageData};

/* tworzenie bitowego obrazu */
#[wasm_bindgen]
pub fn mandel(
    ctx: &CanvasRenderingContext2d, 
    width: u32, height: u32,
    cx: f64, cy: f64) -> Result<(), JsValue> {

    let i_start = -1.92;
    let i_end   = 1.92;
    let j_start = -1.92;
    let j_end   = 1.92;

    let i_delta = (i_end-i_start)/width as f64;
    let j_delta = (j_end-j_start)/height as f64;

    /* obliczenia */    
    let iterations = 255;

    let mut pix_julia = Vec::with_capacity( usize::try_from(width * height).unwrap() );

    let mut j = j_start;
    for _wj in 0..height {

        let mut i = i_start;   
        for _wi in 0..width {
        
            let mut c: u8 = 0;

            let mut x = cx;
            let mut y = cy;
    
            while ( (x*x + y*y) < 4.0) && (c < iterations)
            {
                let _tx = x;
                x = x * x - y * y + i;
                y = 2.0 * _tx * y + j;
                c += 1;
            }

            pix_julia.push( 255-c );
            pix_julia.push( 255-c );
            pix_julia.push( 255-(c/2) );
            pix_julia.push( 255 );
            
            i  += i_delta;
        }
    
        j  += j_delta;
    }    

    let data = ImageData::new_with_u8_clamped_array_and_sh(Clamped(&pix_julia), width, height)?;
    ctx.put_image_data(&data, 0.0, 0.0)
}

The cargo.tomlwas

[package]
name = "hello-wasm"
version = "0.1.0"
edition = "2021"

# See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html

[lib]
crate-type = ["cdylib"]

[dependencies]
wasm-bindgen = "0.2.87"

[dependencies.web-sys]
version = "0.3.4"
features = [
  'Document',
  'Element',
  'HtmlElement',
  'Node',
  'Window',
  'ImageData',
  'CanvasRenderingContext2d'  
]

[profile.release]
opt-level = 3
lto = true

[package.metadata.wasm-pack.profile.release]
wasm-opt = ["-O4", "--enable-mutable-globals"]

and the HTML

<!doctype html>
<html lang="en-US">
  <head>
    <meta charset="utf-8" />
    <title>Mandelbrot</title>
  </head>
  <body>
    <script type="module">
        import init, { mandel } from "./pkg/hello_wasm.js";
        
        (async function() {
		   await init();
           SetupMandel();    
        })();
	  
        var cx = 0, cy = 0, kat1 = 0, kat2 = 1;      
        var WJulia = 1024;
        var HJulia = 1024;        
        var frame  = 0;
		var startDate;
        
        var contextJulia;
        var contextSmall;
        var pixJulia;
        var imgdJulia;

        function SetupMandel()
        {	 
            var elemJulia = document.getElementById('JuliaCanvas');
            if (elemJulia && elemJulia.getContext)
            {
                contextJulia = elemJulia.getContext('2d');
                if (contextJulia)
                {
                    imgdJulia = contextJulia.createImageData(WJulia, HJulia);         
                    pixJulia = imgdJulia.data;
                }
            }
          
		    startDate = new Date();
			
            /* start */
            requestAnimationFrame( LoopMandel );
        }
                         
        function LoopMandel()
        {	 
            kat1 += 0.0021;
            kat2 += 0.0039;
            cx = .681 * Math.sin(kat1);
            cy = .626 * Math.cos(kat2);

            frame++;
            document.getElementById('fps').innerHTML = `FPS: ${1000*frame/(new Date()-startDate)}`;
			
            mandel(contextJulia, WJulia, HJulia, cx, cy);	 
            
            requestAnimationFrame( LoopMandel );
        }	  
    </script>
    <span id="fps" style='display: block'></span>	
    <canvas id="JuliaCanvas" width="1024" height="1024">
	</canvas>	
  </body>
</html>

And the result? Similar, it also makes 10-11 frames per second. Additional tests (different resolution and number of iterations) and possible optimizations can be applied here.

Background music for coding - playlist

It's only an hour or so at the moment but nonetheless - this is a collection of music I listen while coding. I hope to expand the list in future.

Link to the Spotify playlist

Rust binary tree with iterator

For few days I scratch my head over Rust. Never tried it before, not going to be a Rust developer but I feel I'm missing new challenges and this looks like one.

While the official docs are rather concise, there are good books, the Programming Rust: Fast, Safe Systems Development 2nd Edition by Blandy/Orendorff/Tindall is really good and it feels like it's written by folks who really like to help the reader. A lot of good examples and the background I missed in the official docs.

Anyway, my first successfull attempt at something not-that-obvious, a binary tree with an iterator. Doing this in C# would be a breeze, Rust had some surprises around every corner. I am lucky to have Łukasz who answers my questions, corrects my mistakes and gives critical hints on specific problems. Thanks!

The code below. For anyone wondering how much time did it take, starting from zero knowledge of the language to this point - few hours reading the book and then like 5-6 hours to get this result.

use std::fmt::Debug;

struct TreeNode<'a, T: 'a> {
    val  : &'a T,
    left : Option<Box<TreeNode<'a, T>>>,
    right: Option<Box<TreeNode<'a, T>>>
}

impl<'a, T> TreeNode<'a, T> {
    fn new(
        val: &'a T, 
        left: Option<Box<TreeNode<'a, T>>>, 
        right: Option<Box<TreeNode<'a, T>>>) -> Self {
        Self { val, left, right }
    }
}

/* C#'s IEnumerable on TreeNode - returns an iterator/enumerator */
impl<'a, T> IntoIterator for &'a TreeNode<'a, T> {
    type Item = &'a TreeNode<'a, T>;
    type IntoIter = TreeNodeIterator<'a, T>;

    fn into_iter(self) -> Self::IntoIter {
        TreeNodeIterator::init(&self)    
    }
}

/* C#'s IEnumerator */
struct TreeNodeIterator<'a, T: 'a> {
    stack: Vec<&'a TreeNode<'a, T>>
}

impl<'a, T> TreeNodeIterator<'a, T> {
    fn init(node: &'a TreeNode<'a, T>) -> Self {
        Self { stack: vec![node] }
    }
}

impl<'a, T> Iterator for TreeNodeIterator<'a, T> {
    type Item = &'a TreeNode<'a, T>;

    fn next(&mut self) -> Option<Self::Item> {
        
        if self.stack.len() > 0 {

            let curr = self.stack.pop()?;

            /* one way to tackle the child noe */
            if let Some(right) = &curr.right {
                self.stack.push( right.as_ref() );    
            }
            /* another way of doing the same */
            if curr.left.is_some() {
                self.stack.push(curr.left.as_ref().unwrap());
            }

            return Some(curr);
        }

        None
    }
}

/* auxiliary code to be able to test the enumerator */
struct TreeNodeUtility;
impl TreeNodeUtility  {
    fn do_work<'a, T> ( node: &'a TreeNode<'a, T> ) where &'a T: Debug {
        for n in node {
            println!("{:?}", n.val );
        }
    }
}

fn main() {

    let s1 = String::from("1");
    let s2 = String::from("2");
    let s3 = String::from("3");

    let root = Some( TreeNode::<String>::new(
        &s1, 
        
            Some(Box::new(TreeNode::<String>::new(
                &s2,
                None,
                None
            ))), 
        
            Some(Box::new(TreeNode::<String>::new(
                &s3,
                None,
                None
            )))
    ) ) ;

    if root.is_some() {
        let rootc = root.unwrap();
        TreeNodeUtility::do_work( &rootc );
        TreeNodeUtility::do_work( &rootc );
    }
}

After consulting the clippy and trying to improve the code further, I came up with following changes:

• changed the type of the iterator's item to &T from &TreeNode<T>
• changed the TreeNodeIterator to a tupled struct (a struct with just a single field that doesn't even need a name)
• dropped the init method of the iterator struct
• changed the "if non empty stack - pop" code into a single liner
• changed the "if option is some - do" code into a single liner

use std::fmt::Debug;

struct TreeNode<'a, T: 'a> {
    val  : &'a T,
    left : Option<Box<TreeNode<'a, T>>>,
    right: Option<Box<TreeNode<'a, T>>>
}

impl<'a, T> TreeNode<'a, T> {
    fn new(
        val: &'a T, 
        left: Option<Box<TreeNode<'a, T>>>, 
        right: Option<Box<TreeNode<'a, T>>>) -> Self {
        Self { val, left, right }
    }
}

/* C#'s IEnumerable on TreeNode - returns an iterator/enumerator */
impl<'a, T> IntoIterator for &'a TreeNode<'a, T> {
    type Item = &'a T;
    type IntoIter = TreeNodeIterator<'a, T>;

    fn into_iter(self) -> Self::IntoIter {
        TreeNodeIterator(vec![self])
    }
}

/* C#'s IEnumerator */
struct TreeNodeIterator<'a, T: 'a>(Vec<&'a TreeNode<'a, T>>);

impl<'a, T> Iterator for TreeNodeIterator<'a, T> {
    type Item = &'a T;

    fn next(&mut self) -> Option<Self::Item> {
        
        if let Some(curr) = self.0.pop() {

            /* one way to tackle the child node */
            if let Some(right) = &curr.right {
                self.0.push( right.as_ref() );    
            }
            /* another way of doing the same */
            if curr.left.is_some() {
                self.0.push(curr.left.as_ref()?);
            }

            return Some(curr.val);
        }

        None
    }
}

/* auxiliary code to be able to test the enumerator */
struct TreeNodeUtility;
impl TreeNodeUtility  {
    fn do_work<'a, T> ( node: &'a TreeNode<'a, T> ) where &'a T: Debug {
        for n in node {
            println!("{:?}", n );
        }
    }
}

fn main() {

    let s1 = String::from("1");
    let s2 = String::from("2");
    let s3 = String::from("3");

    let root = Some( TreeNode::<String>::new(
        &s1, 
        
            Some(Box::new(TreeNode::<String>::new(
                &s2,
                None,
                None
            ))), 
        
            Some(Box::new(TreeNode::<String>::new(
                &s3,
                None,
                None
            )))
    ) ) ;

    if let Some( rootc ) = root  {
        TreeNodeUtility::do_work( &rootc );
        TreeNodeUtility::do_work( &rootc );
    }
}

Notes to myself-from-the-future

The more code I write over the years, the more additional non-code information I tend to leave to myself from the future. The additional information, put in inline comments, comments in signatures, external markdown files, is intended to be targeted exactly to me from the future.

It usually starts when I look for something. Like for example - an ASP.NET application, something that looks like it works upon each request but there's no visible sign of a public http module registered in web.config. Since that's odd, I go to the global.asax and try to find a module registered programmatically (rather than declaratively). And then I remember - "wait a minute, I remember myself searching for the same information some time ago".

This is where I make a conclusion - if I search for something and I remember searching for it at least once before, I try to think like myself-from-the-future. Where would I search for this information next time? Well, I am in global.asax now, so there's a high probability that the future-me will also come to the global.asax.

I decide to use the global.asax then and I leave a note to myself-from-the-future - If you search for [....], this information is in [....]"

Looking for various information, I then am grateful to myself-from-the-past - I often just stumble upon these "If you search for ... this information is in ...." which means that at some point in the past I tried to think like the present-me and my prediction at that time was correct. And often, I have no memory of writing these notes, I just see them in the code, I belive I wrote them at some point, I can even check the source control and find the exact date. But I just don't remember writing it at all.

All these notes I send to myself, from the past to the future, are nice and useful and somehow let me feel like the past-me and the present-me is for sure the very same me, despite the time that passes. Things change but the way I think about myself is solid.

Today was the day I tried to find something in the code. The code is an old desktop utility app that registers some HTTP listeners at start. There are multiple places listeners can be added, in the Main function, in the main form's constructor, in the main form's load event etc. At first I've assumed the myself-from-the-past would possibly leave a note to the present me somewhere.

I've checked few obvious places. Is there a global markdown file for such notes? Nope. Is there a comment in the main *.cs file? Nope. Is there a comment in the form constructor? Nope. Is there a comment above the form class definition? Yes, there is but the summary section doesn't seem to contain any information about registration of HTTP listeners.

So I've spent like 3 minutes to track down the registration. Found a method that does it. Found a reference to the method. Tracked the reference, until I've ended up in form's Load method.

Just leave a note to myself-from-the-future - I thought. Next time I will try to search for it, I will probably go to main form class and a comment above it. The place that already contains the summary section but lacks the information about listener registrations.

So I go there, go to the very bottom of the summary section, since it spans a dozen of lines I carefully navigate to its ending to put a new line with the new information about the registration of HTTP listeners.

And guess what. The summary section ends, the remarks section starts there, a section I obviously missed few minutes eariler (I just haven't noticed it's there, I thought the whole green block of comment lines was the summary section)!

And the only line in the remarks section is: If you search for registration of HTTP listeners, it's in frmMain_Load

I swear it was not there few minutes ago ... But the fact that I've spent few minutes doing something I thought I hadn't done before but ultimately looks like I had, is kind of reassuring.

C# Puzzle No.25 (intermediate)

Let's have list of references to objects of a custom type that have a state. Let's loop through the list and alter the internal state of each object on the list.

Will the change of the internal state be preserved after the loop ends?

A first answer should of course be yes.

Take a look at this then:

var elements =
    Enumerable.Range(0, 10)
        .Select( i => new Foo() { Bar = i });

foreach ( var e in elements )
{
    // yields 0,1,2,3,4,5,6,7,8,9 which is correct
    Console.WriteLine( e.Bar );
}

foreach ( var e in elements )
{
    e.Bar += 10;

    // yields 10, 11, ...., 19
    Console.WriteLine( e.Bar ); 
}

foreach ( var e in elements )
{
    // yields 0,1,2,3,4,5,6,7,8,9 which doesn't seem correct 
    // (original values restored)!
    Console.WriteLine( e.Bar );
    
    // expected: 10, 11, ..., 19!
}


public class Foo
{
    public int Bar { get; set; }
}

First we create a list of elements. Then we loop it to check if it's correct. Then we loop it to alter the internal state of objects.

Then we loop again and, oddly, it seems like original values are restored.

Not that obvious to spot what's wrong here, a similar issue was caught on production code. The goal is to find a simplest fix.

Unable to generate an explicit migration because the following explicit migrations are pending

There's an old SO question about this, the dreadful Unable to generate an explicit migration because the following explicit migrations are pending.

Not sure if SO answers cover this scenario but this is issue can occur in following setup:

• you have a parameterless DbContext's constructor and also a connection-string parameter constructor
• you generate migrations by adding the -ConnectionString and -ConnectionProviderName parameters of add-migration
• there's no default connection string in the configuration file

The first migration is created correctly but the second one cannot find the migration already applied to the database. Seems it's a bug.

A simple solution is to add a default connection string to the configuration file and drop -ConnectionString and -ConnecitonProviderName from the invocation of add-migration. This picks the default connection string and further checks all new migration against the default database. Still, the other constructor can be used in production code.

public class FooDbContext : DbContext
{
  public FooDbContext() { } // this constructor is used by migration generator
  
  public FooDbContext( string connectionString ) : base( connectionString ) { } // you could be using this from your code
}

Burning Mandelbrot set animation in Javascript

Years ago I've blogged about Julia fractals, I've demonstrated how these can be easily implemented in Javascript. I love to put my hands on this from time to time.

Another interesting experiment occurs when the Julia formula

x0   = coordinates of a point from the plane
xn+1 = xn * xn + c       

is changed to

x0   = 0
xn+1 = xn * xn + coordinates of a point from the plane      

This modified formula leads to the Mandelbrot set. It's one of the most amazing discoveries of the computer science and has many interesting properties.

The only subtle detail that can be improved here is that there's only one Mandlelbrot set, there's no obvious way to make an animation here. With Julias - the animation is created when the c parameter is modified somehow, for example using the Lissajous formula, as shown in my old blog entry.

Can we somehow animate Mandelbrot? Yes! Just change the formula slightly

x0   = c
xn+1 = xn * xn + coordinates of a point from the plane      

so instead of starting from 0, we start from a constant c that again can be modified using the Lissajous formula.

The result is interesting. I've called it the Burning Mandelbrot and honestly, I've never seen it before (although the idea is quite simple).

As a nice addition, I've implemented a simple zoom feature, you can zoom into the image by just clicking the point on the canvas. Enjoy!

X:

Y:

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).