Log to Spans

[enzian]

I there an idiomatic way of getting Logs written to a Span? This would accomplish two things at once - eliminate the need for collecting running console outputs and on the other hand it would enable the user to decouple the code from direcly writing to the logs of the current span... The issue I'm facing here is that I am not really clear on the best method to get something like this done. One solution I cam up with was to write an ILogger and ILoggerFactory that look something like this:

    internal class Factory : ILoggerProvider
    {
        public ILogger CreateLogger(string categoryName)
        {
            return new ToSpanLogger(categoryName);
        }

        public void Dispose()
        {
            // nothing to dispose here...
        }
    }

    internal class ToSpanLogger : ILogger
    {
        private readonly string category;

        public ToSpanLogger(string category)
        {
            this.category = category;
        }

        public TelemetrySpan Span { get; set; }

        public IDisposable BeginScope<TState>(TState state)
        {
            if (state is TelemetrySpan span)
            {
                return new SpanScope(this, span);
            }

            return null;
        }

        public bool IsEnabled(LogLevel logLevel)
        {
            return true;
        }

        public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
        {
            if (this.Span != null)
            {
                if (logLevel == LogLevel.Error)
                {
                    Span.SetAttribute("error", true);
                }
                Span.AddEvent(formatter(state, exception));
            }
        }
    }

    internal class SpanScope : IDisposable
    {
        public SpanScope(ToSpanLogger logger, TelemetrySpan span)
        {
            Logger = logger;
            Logger.Span = span;
        }

        public ToSpanLogger Logger { get; }

        public void Dispose()
        {
            Logger.Span = null;
        }
    }
}

which could then be used like this:

var span = tracer.StartRootSpan("test", SpanKind.Client, new SpanCreationOptions {});
var logger = scope.ServiceProvider.GetRequiredService<ILogger<Type>>();
using (var logscope = logger.BeginScope(span))
{
    logger.LogInformation("starting here");
    DoSomeWork();
    logger.LogError("ended in desaster");
}
span.End();

[cijothomas]

@reyang was doing experiments on something similar. Can you comment on this?

[reyang]

@enzian would you clarify the goal here? It seems that you want logs from ILogger to be attached as Span Events - why would you want to take this approach?

• In OpenTelemetry, logs are separate from traces (spans), logs are different from span events as they following different processing and sampling path.
• Calling a logger.LogError shouldn't have side effect to span status.

[enzian]

@reyang I am aware, that event != logs. There is two reasons for me wanting to use them to carry logging information though. Please correct me if I'm going wrong on any of them or if there are better or more ideomatic solutions to any of these problems.

The first problem is, that I want to decouple my code for as many depencencies as possible. The way I'd have to record things right now is to write a log and write one or more lines to write a corresponding event. This introduces two dependencies into my code, one on ILogger<T> and one on Span, log on one and record events on the other. Since I would not necessarly need to depend on Span I'd like to remove this dependency.

The other problem is the correlation between logs and traces. While there are a number of system that can collect logs none of them (as far as I know) are able to correlate this to a span in say Jaeger. This is why I would like to use the span to carry this information.

I'm ready to be shown the errors of my ways :-)

[reyang]

The first problem is, that I want to decouple my code for as many depencencies as possible. The way I'd have to record things right now is to write a log and write one or more lines to write a corresponding event. This introduces two dependencies into my code, one on ILogger<T> and one on Span, log on one and record events on the other. Since I would not necessarly need to depend on Span I'd like to remove this dependency.

This doesn't sound correct to me. Logs/Metrics/Traces are very different things and the OpenTelemetry philosophy is to separate them via different set of APIs. Technically speaking, one could use metrics API for logging and put all the information as dimensions, or use logging API for metrics by putting dimensions as individual fields for a log entry - I don't think OpenTelemetry would encourage such behavior.

The other problem is the correlation between logs and traces. While there are a number of system that can collect logs none of them (as far as I know) are able to correlate this to a span in say Jaeger. This is why I would like to use the span to carry this information.

Log correlation is an important feature that are supported by several systems and components.
For ILogger the correlation is available in the preview package, and will GA before end of 2020:

class Program
{
    static readonly ActivitySource source = new ActivitySource("DemoSource");

    static void Main()
    {
        using var loggerFactory = LoggerFactory.Create(builder =>
        {
            builder.AddConsole(options => { options.IncludeScopes = true; });
            builder.Configure(options => options.ActivityTrackingOptions =
                ActivityTrackingOptions.TraceId |
                ActivityTrackingOptions.SpanId |
                ActivityTrackingOptions.TraceFlags
            );
        });
        var logger = loggerFactory.CreateLogger<Program>();

        using (var activity = source.StartActivity("SayHello"))
        {
            logger.LogInformation("Hello from ILogger!");
        }
    }
}