Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

otel.status_code not set if Activity.SetStatus(ActivityStatusCode) is called #3045

Closed
nathansoz opened this issue Mar 15, 2022 · 4 comments
Closed
Labels
bug Something isn't working

Comments

@nathansoz
Copy link

nathansoz commented Mar 15, 2022

Bug Report

List of all OpenTelemetry NuGet
packages
and version that you are
using (e.g. OpenTelemetry 1.0.2):

OpenTelemetry Latest

Runtime version (e.g. net461, net48, netcoreapp3.1, net5.0 etc. You can
find this information from the *.csproj file):

.NET 6.x

Symptom

If I call activity.SetStatus(ActivityStatusCode.Error) the property otel.status_code is not set. If I call activity.SetStatus(Status.Error) the property otel.status_code is set. This is confusing behavior at best and exporters don't seem to handle it even though the activity itself is reported as an error.

What is the expected behavior?
otel.status_code should be set (maybe this should be done by convention in exporters?).

What did you expect to see?
otel.status_code set.

What is the actual behavior?
otel.status_code is not set. This is especially bad in the case of exporters that are looking for otel.status_code.

What did you see instead?

Reproduce

using System;
using System.Diagnostics;
using System.Net.Http;
using System.Runtime.InteropServices;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.Hosting;
using Microsoft.Extensions.Logging;
using OpenTelemetry;
using OpenTelemetry.Logs;
using OpenTelemetry.Trace;

namespace Test
{
    public class Program
    {
        private static readonly ActivitySource MyActivitySource = new ActivitySource("MyCompany.MyProduct.MyLibrary");
        public static async Task Main(string[] args)
        {
            using var tracerProvider = Sdk.CreateTracerProviderBuilder()
                .SetSampler(new AlwaysOnSampler())
                .AddSource("MyCompany.MyProduct.MyLibrary")
                .SetErrorStatusOnException(false)
                .AddConsoleExporter()
                .AddHttpClientInstrumentation()
                .Build();

            using var loggerFactory = LoggerFactory.Create(builder =>
            {
                builder.AddOpenTelemetry(options => options
                    .AddConsoleExporter());
            });

            var logger = loggerFactory.CreateLogger<Program>();

            logger.LogInformation("Running on: {platform}", RuntimeInformation.OSDescription);

                        var listener = new ActivityListener
            {
                ActivityStopped = (a) =>
                {
                    if (string.IsNullOrWhiteSpace(a?.DisplayName))
                    {
                        return;
                    }

                    logger.LogInformation("Activity {activity} had status {status}", a.DisplayName, a.Status);
                    var status = a.GetStatus();
                },
                ShouldListenTo = s => true,
                Sample = (ref ActivityCreationOptions<ActivityContext> _) => ActivitySamplingResult.AllData,
            };

            ActivitySource.AddActivityListener(listener);

            await LogOperationAsync("Test", (c) => Bar());

            tracerProvider.Shutdown();
        }
        private static async Task Bar()
        {
            await Task.Delay(100);
            try
            {
                await LogOperationAsync("Bar2", (c) => Bar2());
            }
            catch
            {
                // do nothing
            }
        }

        private static async Task Bar2()
        {
            await Task.Delay(100);
            throw new Exception("Oops!");
        }

        public async static Task LogOperationAsync(string operationName, Func<CancellationToken, Task> operation, bool swallowExceptions = false, CancellationToken cancel = default)
        {
            using var activity = MyActivitySource.StartActivity(operationName);

            bool success = false;
            try
            {
                await operation(cancel);
                success = true;
            }
            catch (Exception ex)
            {
                RecordException(activity, ex);

                if (!swallowExceptions)
                {
                    throw;
                }
            }
            finally
            {
                activity?.SetStatus(success ? ActivityStatusCode.Ok : ActivityStatusCode.Error);
            }
        }

        private static void RecordException(Activity activity, Exception exception)
        {
            if (activity == null || exception == null)
            {
                return;
            }

            // Events are not recorded by the geneva exporter, so also attach as tags.
            activity?.AddTag("test.exception.type", exception.GetType().FullName);
            activity?.AddTag("test.exception.stacktrace", exception.ToString());
            if (!string.IsNullOrWhiteSpace(exception.Message))
            {
                activity?.AddTag("test.exception.message", exception.Message);
            }
        }
    }
}

Results in:

LogRecord.TraceId:            00000000000000000000000000000000
LogRecord.SpanId:             0000000000000000
LogRecord.Timestamp:          2022-03-15T06:22:09.8407950Z
LogRecord.EventId:            0
LogRecord.CategoryName:       Test.Program
LogRecord.LogLevel:           Information
LogRecord.TraceFlags:         None
LogRecord.State:              Running on: Darwin 21.3.0 Darwin Kernel Version 21.3.0: Wed Jan  5 21:37:58 PST 2022; root:xnu-8019.80.24~20/RELEASE_ARM64_T6000
Resource associated with LogRecord:
    service.name: unknown_service:scratch

Activity.Id:          00-db2cb754616a4eba37e984a560c20201-83b3a0a3d408bfc8-01
Activity.ParentId:    00-db2cb754616a4eba37e984a560c20201-b506f2788afb2d90-01
Activity.ActivitySourceName: MyCompany.MyProduct.MyLibrary
Activity.DisplayName: Bar2
Activity.Kind:        Internal
Activity.StartTime:   2022-03-15T06:22:09.9988950Z
Activity.Duration:    00:00:00.1715830
Activity.TagObjects:
    test.exception.type: System.Exception
    test.exception.stacktrace: System.Exception: Oops!
   at Test.Program.Bar2() in /Users/nsosnov/source/z.nsosnov/opentelemetry-repro/Program.cs:line 76
   at Test.Program.LogOperationAsync(String operationName, Func`2 operation, Boolean swallowExceptions, CancellationToken cancel) in /Users/nsosnov/source/z.nsosnov/opentelemetry-repro/Program.cs:line 86
    test.exception.message: Oops!
Resource associated with Activity:
    service.name: unknown_service:scratch

LogRecord.TraceId:            db2cb754616a4eba37e984a560c20201
LogRecord.SpanId:             83b3a0a3d408bfc8
LogRecord.Timestamp:          2022-03-15T06:22:10.1744000Z
LogRecord.EventId:            0
LogRecord.CategoryName:       Test.Program
LogRecord.LogLevel:           Information
LogRecord.TraceFlags:         Recorded
LogRecord.State:              Activity Bar2 had status Error
Resource associated with LogRecord:
    service.name: unknown_service:scratch

Activity.Id:          00-db2cb754616a4eba37e984a560c20201-b506f2788afb2d90-01
Activity.ActivitySourceName: MyCompany.MyProduct.MyLibrary
Activity.DisplayName: Test
Activity.Kind:        Internal
Activity.StartTime:   2022-03-15T06:22:09.8904700Z
Activity.Duration:    00:00:00.2873780
Resource associated with Activity:
    service.name: unknown_service:scratch

LogRecord.TraceId:            db2cb754616a4eba37e984a560c20201
LogRecord.SpanId:             b506f2788afb2d90
LogRecord.Timestamp:          2022-03-15T06:22:10.1780240Z
LogRecord.EventId:            0
LogRecord.CategoryName:       Test.Program
LogRecord.LogLevel:           Information
LogRecord.TraceFlags:         Recorded
LogRecord.State:              Activity Test had status Ok
Resource associated with LogRecord:
    service.name: unknown_service:scratch

We will close this issue if:

  • The repro project you share with us is complex. We can't investigate custom
    projects, so don't point us to such, please.
  • If we can not reproduce the behavior you're reporting.

Additional Context

Add any other context about the problem here.

@nathansoz nathansoz added the bug Something isn't working label Mar 15, 2022
@vishweshbankwar
Copy link
Member

This issue is currently being tracked here
#2569

@cijothomas
Copy link
Member

Closing as duplicate. We are hoping to ship the fix in 1.2 itself.

@cijothomas
Copy link
Member

otel.status_code should be set (maybe this should be done by convention in exporters?).

^ Yes. its a convention/temp workaround until Activity added native support for Status (occured in Sys.Diagnostic. version 6.0)

@Yun-Ting
Copy link
Contributor

At 2/8/2022 SIG meeting,
the community agreed to go with the first option:
ActivityStatus migration
@cijothomas: prefers to let every Exporters deal with it than handling it in SDK
Modify all core exporters from this repo to handle this
Modify “Write own exporter” doc to talk about things changing between each .NET versions.

The pros of supporting setting status with native Status in all the Exporters are:

Prevent perf penalty in enumerating all the activity tags in the core SDK.
Less maintenance/migration effort when the time comes on stop supporting setting status via activity tags.
This is the first PR to add support for activity status and ActivityStatusDescription in 6.0.0 version of System.Diagnostic.DiagnosticSource.
There will be follow-up PRs to add support to other Exporters.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

4 participants