Console/Debug logging in unit tests?

[PhasonMatrix]

I can get console logging from python code working, with the following code:

Program.cs from template with some code added based on the troubleshooting section of the documentation here https://tonybaloney.github.io/CSnakes/v1/advanced/troubleshooting/#python-debugging

using System;
using System.IO;
using CSnakes.Runtime;
using CSnakes.Runtime.Locators;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Hosting;
using Microsoft.Extensions.Logging;

var pythonHomePath = AppContext.BaseDirectory;

var builder = Host.CreateApplicationBuilder(args);
builder.Services
       .WithPython()
       .WithHome(pythonHomePath)
       .FromRedistributable(RedistributablePythonVersion.Python3_12)
       .WithVirtualEnvironment(Path.Combine(pythonHomePath, ".venv"))
       .WithPipInstaller();

// Configure logging in Program.cs
builder.Logging.AddConsole();
builder.Logging.SetMinimumLevel(LogLevel.Debug);

// Add specific logging for CSnakes
builder.Logging.AddFilter("CSnakes", LogLevel.Debug);

var app = builder.Build();
var env = app.Services.GetRequiredService<IPythonEnvironment>();

var hello = env.Hello();
Console.WriteLine(hello.Greetings("World"));

hello.py from template, also with code added from troubleshooting documentation

import logging
import sys

logging.basicConfig(level=logging.DEBUG)
logger = logging.getLogger(__name__)

def greetings(name: str) -> str:
    logger.debug(f"Input received: {name}")
    logger.debug(f"Python version: {sys.version}")
    logger.debug(f"Python path: {sys.path}")
    return f"Hello, {name}!"

This works and I see the log messages from the python code.

But when I try to do the same thing from a unit test (XUnit)...

using CSnakes.Runtime;
using CSnakes.Runtime.Locators;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Hosting;
using Microsoft.Extensions.Logging;

namespace UnitTests;

public class CommunicationTests
{

    IPythonEnvironment _env;

    public CommunicationTests()
    {
        // Setup code here
        var pythonHomePath = AppContext.BaseDirectory;

        var builder = Host.CreateApplicationBuilder(new string[0]);
        builder.Services
               .WithPython()
               .WithHome(pythonHomePath)
               .FromRedistributable(RedistributablePythonVersion.Python3_12)
               .WithVirtualEnvironment(Path.Combine(pythonHomePath, ".venv"))
               .WithPipInstaller();

        builder.Logging.AddConsole();
        builder.Logging.AddDebug();
        builder.Logging.SetMinimumLevel(LogLevel.Debug);
        // Add specific logging for CSnakes
        builder.Logging.AddFilter("CSnakes", LogLevel.Debug);

        var app = builder.Build();
        _env = app.Services.GetRequiredService<IPythonEnvironment>();
        _env.Logger?.LogDebug("Python Environment initialized");
    }

    [Fact]
    public void GreetingTest()
    {
        string name = "Fred";

        var pyCommunicationTestModule = _env.PyCommunicationTest();
        string greetingResult = pyCommunicationTestModule.Greetings(name);

        Assert.Equal("Hello, Fred!", greetingResult);
    }

}

py_communication_test.py

import logging
import sys

logging.basicConfig(level=logging.DEBUG)
logger = logging.getLogger(__name__)

def greetings(name: str) -> str:
    logger.debug(f"Input received: {name}")
    logger.debug(f"Python version: {sys.version}")
    logger.debug(f"Python path: {sys.path}")
    return f"Hello, {name}!"

I DO see log messages from the generated C# code, like Debug: Invoking Python function: greetings, but I DO NOT see the log messages from the python code stating the input received, python version, and python path.

Is there something else I need to do to get it to work in unit tests? Mock a console? Create an in Memory console? I tried these base on suggestions from AI code assistants but I got the same behaviour.

[atifaziz]

Is there something else I need to do to get it to work in unit tests? Mock a console?

I would recommend reading up on capturing output in xUnit.net documentation.

Capturing the logging from Python might need more work. One way is to obtain a ITestOutputHelper in your test class constructor:

public class CommunicationTests
{
    ITestOutputHelper _output;
    IPythonEnvironment _env;

    public CommunicationTests(ITestOutputHelper output)
    {
        _output = output;

        // rest of the method code...
    }
}

Then update the Python module to redirect to a stream backed by a string and adding another function (get_log below) to obtain its content like so:

import io
import logging
import sys

stream = io.StringIO()
logging.basicConfig(level=logging.DEBUG, stream=stream)
logger = logging.getLogger(__name__)

def get_log() -> str:
    return stream.getvalue()


def greetings(name: str) -> str:
    logger.debug(f"Input received: {name}")
    logger.debug(f"Python version: {sys.version}")
    logger.debug(f"Python path: {sys.path}")
    return f"Hello, {name}!"

Finally, back in C#, in your test method, get the content of the log like this and emit to the output helper from xUnit.net:

[Fact]
public void GreetingTest()
{
    string name = "Fred";

    var pyCommunicationTestModule = _env.PyCommunicationTest();
    try
    {
        var greetingResult = pyCommunicationTestModule.Greetings(name);

        Assert.Equal("Hello, Fred!", greetingResult);
    }
    finally
    {
        var reader = new StringReader(pyCommunicationTestModule.GetLog());
        while (reader.ReadLine() is { } line)
            _output.WriteLine(line);
    }
}

Hope this helps.

[PhasonMatrix]

Thanks Atif. I tried that and it worked well. But seeing this code gave me a couple of ideas to make a much simpler solution. I'll make note of some code here for myself and anyone else looking for this in the future.

I can use System.Diagnostics.Debug to write the captured logs, eliminating the need for Xunit.Abstractions.ITestOutputHelper. This will write the log messages to the Debug Output window in Visual Studio as apposed to the Test Details Summary, which is fine by me.

while (reader.ReadLine() is { } line)
    Debug.WriteLine(line);

I can also simply use a string or list of string in the python code as the log and have a getter function to retrieve it like you would for a class field/property, even though the module is not a python class. No log level captured this way but I don't need that. Just need some way to debug what's happening inside the python code

import sys

log = []

def get_log() -> list[str]:
    return log


def greetings(name: str) -> str:
    log.append(f"Input received: {name}")
    log.append(f"Python version: {sys.version}")
    log.append(f"Python path: {sys.path}")
    return f"Hello, {name}!"

and then output it in the unit test with

var logs = pyCommunicationTestModule.GetLog();
foreach (var line in logs)
{
    Debug.WriteLine(line);
}