Serilog output to hangfire context console

Question

I would like to be able to use my Log to emit events through Hangfires context.console, so that I don't need to use context.writeline to output log events to my hangfire dashboard.

I have attempted to implement a specific serilog sink for this purpose. But as I need the PerformContext from hangfire (which is injected during runtime into the task method), I can't configure the log sink at application startup. I have attempted to create a new logger inside the task method, just to see if the sink actually works, and it does not - can anyone either see why it wouldn't work, or maybe suggest a different approach?

Here is the sink:

 class HangfireContextSink : ILogEventSink {
        private readonly IFormatProvider formatProvider;
        private readonly PerformContext context;
        public HangfireContextSink(IFormatProvider formatProvider, PerformContext context) {
            this.formatProvider = formatProvider;
            this.context = context;
        }
        public void Emit(LogEvent logEvent) {
            var message = logEvent.RenderMessage(formatProvider);
            context.WriteLine(ConsoleTextColor.Blue, DateTimeOffset.Now.ToString() + " " + message);
        }

The sink configuration:

 public static class SinkExtensions {
        public static LoggerConfiguration HangfireContextSink(this LoggerSinkConfiguration loggerSinkConfiguration, PerformContext context, IFormatProvider formatProvider = null) {
            return loggerSinkConfiguration.Sink(new HangfireContextSink(formatProvider, context));
        }
    }

The task method:

 public static bool TestJob(PerformContext context) {
            using (LogContext.PushProperty("Hangfirejob", "TestJob")) {
                try {
                    using (var hangfireLog = new LoggerConfiguration().WriteTo.HangfireContextSink(context).CreateLogger()) {
                        var progress = context.WriteProgressBar("Progress");
                        for (int i = 0; i < 10; i++) {
                            context.WriteLine("Working with {0}", i);
                            progress.SetValue((i + 1) * 10);
                            Log.Debug("Test serilog");
                            hangfireLog.Debug("Test from hangfirelog");
                            Thread.Sleep(5000);
                        }
                    }
                    Log.Debug("Done testjob");
                    return true;
                } catch (Exception ex) {
                    Log.Error(ex, "Error!");
                    return false;
                }
            }
        }

Vorous

Answer 1

Messages aren't logged to Hangfire console, because you log them with Debug log level, while default Serilog level is Information. You could change logging level with call to .MinimumLevel.Debug() on LoggerConfiguration. Also for logging messages via Serilog.Log static class, you should set its Logger property.

Here is a fixed code that will log to Hangfire console:

using (LogContext.PushProperty("Hangfirejob", "TestJob"))
{
    try
    {
        using (var hangfireLog = new LoggerConfiguration().MinimumLevel.Debug().WriteTo.HangfireContextSink(context).CreateLogger())
        {
            //  This is a dirty code that will be removed in final solution
            var prevLogger = Log.Logger;
            Log.Logger = hangfireLog;

            var progress = context.WriteProgressBar("Progress");
            for (int i = 0; i < 10; i++)
            {
                context.WriteLine("Working with {0}", i);
                progress.SetValue((i + 1) * 10);
                Log.Debug("Test serilog");
                hangfireLog.Debug("Test from hangfirelog");
                Thread.Sleep(5000);
            }
            Log.Debug("Done testjob");
            Log.Logger = prevLogger;
        }
        return true;
    }
    catch (Exception ex)
    {
        Log.Error(ex, "Error!");
        return false;
    }
}

This will work, however overall approach of creating new log for each job is pretty bad. You could avoid this by passing instance of PerformContext through property in LogEvent. You should define a custom property class that is derived from abstract LogEventPropertyValue and exposes instance of PerformContext.

Here is the final code:

PerformContextProperty.cs:

public class PerformContextProperty : LogEventPropertyValue
{
    public PerformContext PerformContext { get; }

    public PerformContextProperty(PerformContext performContext)
    {
        PerformContext = performContext;
    }

    public override void Render(TextWriter output, string format = null, IFormatProvider formatProvider = null)
    {
    }
}

PerformContextEnricher.cs:

public class PerformContextEnricher : ILogEventEnricher
{
    private readonly PerformContext performContext;

    public PerformContextEnricher(PerformContext performContext)
    {
        this.performContext = performContext;
    }

    public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
    {
        logEvent.AddPropertyIfAbsent(new LogEventProperty(HangfireContextSink.PerformContextProperty, new PerformContextProperty(performContext)));
    }
}

TestJob.cs:

public class TestJob
{
    public static bool Execute(PerformContext context)
    {
        using (LogContext.PushProperty("Hangfirejob", "TestJob"))
        using (LogContext.Push(new PerformContextEnricher(context)))
        {
            try
            {
                var progress = context.WriteProgressBar("Progress");
                for (int i = 0; i < 10; i++)
                {
                    context.WriteLine("Working with {0}", i);
                    progress.SetValue((i + 1) * 10);
                    Log.Debug("Test serilog", context);
                    Log.Debug("Test from hangfirelog");
                    Thread.Sleep(5000);
                }
                Log.Debug("Done testjob");
                return true;
            }
            catch (Exception ex)
            {
                Log.Error(ex, "Error!");
                return false;
            }
        }
    }
}

HangfireContextSink.cs:

class HangfireContextSink : ILogEventSink
{
    public const string PerformContextProperty = "PerformContext";

    private readonly IFormatProvider formatProvider;

    public HangfireContextSink(IFormatProvider formatProvider)
    {
        this.formatProvider = formatProvider;
    }

    public void Emit(LogEvent logEvent)
    {
        var message = logEvent.RenderMessage(formatProvider);

        LogEventPropertyValue propertyValue;
        if (logEvent.Properties.TryGetValue(PerformContextProperty, out propertyValue))
        {
            var context = (propertyValue as PerformContextProperty)?.PerformContext;
            context?.WriteLine(ConsoleTextColor.Green, DateTimeOffset.Now + " " + message);
        }
    }
}

SinkExtensions.cs:

public static class SinkExtensions
{
    public static LoggerConfiguration HangfireContextSink(this LoggerSinkConfiguration loggerSinkConfiguration, IFormatProvider formatProvider = null)
    {
        return loggerSinkConfiguration.Sink(new HangfireContextSink(formatProvider));
    }
}

Serilog configuration:

Log.Logger = new LoggerConfiguration()
    .Enrich.FromLogContext()
    .MinimumLevel.Debug()
    .WriteTo.HangfireContextSink()
    .CreateLogger();

In Serilog configuration don't forget to call .Enrich.FromLogContext() so that log events are enriched with properties from LogContext.

Above code is pretty straightforward, that's why I don't comment it in detail. If you have some questions regarding the code, please ask and I'll try to explain unclear moments.

Spectacled

I'm skimming it over now, out of work, and it looks exactly like I wanted - I was aware that the disposable log for each hangfire job was very messy (and I can't believe I forgot about the minimumlevel!). The enricher approach looks like exactly what I need for the "pretty" approach - thanks a lot! – Vorous

Quick follow-up - I have an issue where using this sink blocks output to other sinks. I can't seem to figure out where the blockage occurs, and it doesn't matter which sink is chained first in the loggerconfiguration. The Context on hangfire receives messages, but the other sinks don't :/ – Vorous

I seem to have narrowed it down - it wasn't blocking all sinks, only SEQ sink, and it appears to be a formatting issue, since SEQ sink requires json formattable property values. I'm looking into a simple fix right now – Vorous

I changed the PerformContextProperty to inherit from ScalarValue instead of the base abstract class. Should probably figure out how to properly render the property to support json formatting, but I just needed the quick fix for now. – Vorous

You could fix this problem by removing throw of NotImplementedException in Render() method of PerformContextProperty class. I have edited it my answer - just leave this method with an empty body. It's ok because PerformContextProperty.Render() will be called only for PerformContext property which does not bring any useful payload. However this approach will output PerformContext property with value of empty string in result json. I hope this is not a problem for you, because there is no easy way to suppress added property from the output. – Spectacled

I did try the empty render method (and tried producing what I thought would be json formattable content in the render method as well) - but I had no luck in any of my attempts. Inheriting the ScalarValue was an easy fix and isn't causing any side-effects, so I'm happy with that solution - thanks for your help! – Vorous