opentelemetry-dotnet icon indicating copy to clipboard operation
opentelemetry-dotnet copied to clipboard

[bug] Exporting logs with OtlpExporter and grpc not working.

Open pravinpushkar opened this issue 9 months ago • 21 comments
trafficstars

Package

OpenTelemetry

Package Version

Package Name Version
OpenTelemetry.Api 1.11.1
OpenTelemetry 1.11.1
TBD TBD

Runtime Version

8

Description

This seems still reproducible with 1.11.1.

Related issue - https://github.com/open-telemetry/opentelemetry-dotnet/issues/6067 https://github.com/open-telemetry/opentelemetry-dotnet/pull/6083

Steps to Reproduce

Here is samle code -

string loggingendpoint = Environment.GetEnvironmentVariable("LOGGING_GRPC_ENDPOINT") ?? "localhost";

if (string.IsNullOrEmpty(loggingendpoint))
{
    Console.WriteLine("No logging endpoint provided.");
}
AppContext.SetSwitch("System.Net.Http.SocketsHttpHandler.Http2UnencryptedSupport", true);

Console.WriteLine($"Logging endpoint: {loggingendpoint}");
using var loggerFactory = LoggerFactory.Create(builder =>
{
    builder.AddOpenTelemetry(options =>
    {
        options.IncludeScopes = true;
        options.IncludeFormattedMessage = true;
        options.AddConsoleExporter();
        options.AddOtlpExporter((exOpt, pOpts) =>
        {
            exOpt.Endpoint = new Uri($"http://{loggingendpoint}");
            exOpt.Protocol = OtlpExportProtocol.Grpc;
        });
    });
});

var logger = loggerFactory.CreateLogger("Log");

using (logger.BeginScope(new List<KeyValuePair<string, object>>{
                    new KeyValuePair<string, object>("category", "OTLPLOGExporter"),
                }))
{
    logger.LogInformationWithDetails($"LOGGING_GRPC_ENDPOINT {loggingendpoint}");

    logger.LogInformationWithDetails("All Done!");
    // to flush the in-memory buffer and ensure all logs are exported.

    loggerFactory.Dispose();
}

Expected Result

Logs successfully exported

Actual Result

Logs not able to get exported. No errors.

Additional Context

No response

pravinpushkar avatar Feb 19 '25 06:02 pravinpushkar

To make it your example working I need to change LogInformationWithDetails to LogInformation and I changed localhost to localhost:4317.

Results (same for .NET8 and .NET9):

splunk-collector-1  | 2025-02-19T11:38:16.318Z  info    ResourceLog #0
splunk-collector-1  | Resource SchemaURL:
splunk-collector-1  | Resource attributes:
splunk-collector-1  |      -> telemetry.sdk.name: Str(opentelemetry)
splunk-collector-1  |      -> telemetry.sdk.language: Str(dotnet)
splunk-collector-1  |      -> telemetry.sdk.version: Str(1.11.1)
splunk-collector-1  |      -> service.name: Str(unknown_service:dotnet-6142)
splunk-collector-1  | ScopeLogs #0
splunk-collector-1  | ScopeLogs SchemaURL:
splunk-collector-1  | InstrumentationScope Log
splunk-collector-1  | LogRecord #0
splunk-collector-1  | ObservedTimestamp: 2025-02-19 11:38:16.1039371 +0000 UTC
splunk-collector-1  | Timestamp: 2025-02-19 11:38:16.1039371 +0000 UTC
splunk-collector-1  | SeverityText: Information
splunk-collector-1  | SeverityNumber: Info(9)
splunk-collector-1  | Body: Str(LOGGING_GRPC_ENDPOINT localhost:4317)
splunk-collector-1  | Attributes:
splunk-collector-1  |      -> {OriginalFormat}: Str(LOGGING_GRPC_ENDPOINT localhost:4317)
splunk-collector-1  |      -> category: Str(OTLPLOGExporter)
splunk-collector-1  | Trace ID:
splunk-collector-1  | Span ID:
splunk-collector-1  | Flags: 0
splunk-collector-1  | LogRecord #1
splunk-collector-1  | ObservedTimestamp: 2025-02-19 11:38:16.1244879 +0000 UTC
splunk-collector-1  | Timestamp: 2025-02-19 11:38:16.1244879 +0000 UTC
splunk-collector-1  | SeverityText: Information
splunk-collector-1  | SeverityNumber: Info(9)
splunk-collector-1  | Body: Str(All Done!)
splunk-collector-1  | Attributes:
splunk-collector-1  |      -> {OriginalFormat}: Str(All Done!)
splunk-collector-1  |      -> category: Str(OTLPLOGExporter)
splunk-collector-1  | Trace ID:
splunk-collector-1  | Span ID:
splunk-collector-1  | Flags: 0
splunk-collector-1  |   {"kind": "exporter", "data_type": "logs", "name": "debug/debug"}

Could you please prepare more detailed steps to reproduce? docker compose file could be beneficial to reproduce it.

Kielek avatar Feb 19 '25 11:02 Kielek

@Kielek Thanks a lot for responding quickly.

I need to change LogInformationWithDetails to LogInformation and I changed localhost to localhost:4317.

Sorry, These are my local setup method and need to change it accordingly. The output above shows from console exporter, which work fine for me as well with docker a image. These logs are not actually reaching the grpc receiver.

The same code when I use it with 1.10.0 open telemetry SDK, it works fine and logs are reaching the grpc receiver.

pravinpushkar avatar Feb 19 '25 12:02 pravinpushkar

It is debug log from the collector with grpc receiver

Kielek avatar Feb 19 '25 13:02 Kielek

ok, it it a bit strange that this code works with 1.10.0 but not with 1.11.1.

pravinpushkar avatar Feb 21 '25 08:02 pravinpushkar

As you see, it is working with 1.11.1 for me. Can you share Minimal, Reproducible Example?

Kielek avatar Feb 21 '25 09:02 Kielek

@pravinpushkar This could be related to https://github.com/open-telemetry/opentelemetry-dotnet/issues/6138. Can you validate this?

rajkumar-rangaraj avatar Feb 21 '25 16:02 rajkumar-rangaraj

@pravinpushkar did you check you are running .NET8 and not .NET6? I had the same issue and it was regarding .NET6..

jlaherran avatar Mar 03 '25 12:03 jlaherran

Can you check how you're ending the application? The OTLP exporter runs on a batch interval, so if you end your application too soon, then it may cause an issue that you're finishing before it's exported.

Also check out the self diagnostics to see if there's a failure connecting to your backend.

https://github.com/open-telemetry/opentelemetry-dotnet/blob/main/src/OpenTelemetry/README.md#self-diagnostics

martinjt avatar Mar 03 '25 19:03 martinjt

I'm getting these exceptions using .NET6 Request to http://localhost:4317/opentelemetry.proto.collector.logs.v1.LogsService/Export failed, the response ended prematurely. Just targeting to .NET8 it works as expected. 2025-03-03T21:49:11.7761154Z:HTTP request to {0} failed. Exception: {1}{http://localhost:4317/opentelemetry.proto.collector.logs.v1.LogsService/Export}{System.Net.Http.HttpRequestException: An error occurred while sending the request. ---> System.IO.IOException: The response ended prematurely. at System.Net.Http.HttpConnection.FillAsync(Boolean async) at System.Net.Http.HttpConnection.ReadNextResponseHeaderLineAsync(Boolean async, Boolean foldedHeadersAllowed) at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) --- End of inner exception stack trace --- at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) at System.Net.Http.DiagnosticsHandler.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken) at OpenTelemetry.Exporter.OpenTelemetryProtocol.Implementation.ExportClient.OtlpGrpcExportClient.SendExportRequest(Byte[] buffer, Int32 contentLength, DateTime deadlineUtc, CancellationToken cancellationToken)} 2025-03-03T21:49:16.4035498Z:HTTP request to {0} failed. Exception: {1}{http://localhost:4317/opentelemetry.proto.collector.trace.v1.TraceService/Export}{System.Net.Http.HttpRequestException: An error occurred while sending the request. ---> System.IO.IOException: The response ended prematurely. at System.Net.Http.HttpConnection.FillAsync(Boolean async) at System.Net.Http.HttpConnection.ReadNextResponseHeaderLineAsync(Boolean async, Boolean foldedHeadersAllowed) at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) --- End of inner exception stack trace --- at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) at System.Net.Http.DiagnosticsHandler.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken) at OpenTelemetry.Exporter.OpenTelemetryProtocol.Implementation.ExportClient.OtlpGrpcExportClient.SendExportRequest(Byte[] buffer, Int32 contentLength, DateTime deadlineUtc, CancellationToken cancellationToken)} 2025-03-03T21:49:17.1738538Z:HTTP request to {0} failed. Exception: {1}{http://localhost:4317/opentelemetry.proto.collector.logs.v1.LogsService/Export}{System.Net.Http.HttpRequestException: An error occurred while sending the request. ---> System.IO.IOException: The response ended prematurely. at System.Net.Http.HttpConnection.FillAsync(Boolean async) at System.Net.Http.HttpConnection.ReadNextResponseHeaderLineAsync(Boolean async, Boolean foldedHeadersAllowed) at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) --- End of inner exception stack trace --- at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) at System.Net.Http.DiagnosticsHandler.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken) at OpenTelemetry.Exporter.OpenTelemetryProtocol.Implementation.ExportClient.OtlpGrpcExportClient.SendExportRequest(Byte[] buffer, Int32 contentLength, DateTime deadlineUtc, CancellationToken cancellationToken)}

jlaherran avatar Mar 03 '25 22:03 jlaherran

@pravinpushkar Could you please try with the latest version 1.11.2 and check if it works now?

rajkumar-rangaraj avatar Mar 05 '25 02:03 rajkumar-rangaraj

It doesn't work with 1.11.2 as well (tested using .Net 9 runtime).

Exporting works (and is visible, e.g., in Aspire Dashboard) when you use the web stack, meaning when you start building the stack using WebApplication.CreateBuilder(args).

It does not work when you try to build the stack manually, starting the definition with Host.CreateDefaultBuilder(args) or manually creating the Logger configuration, as is the case described in this ticket.

stalek71 avatar Mar 19 '25 10:03 stalek71

Minimal example:

using System.Diagnostics;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Hosting;
using Microsoft.Extensions.Logging;
using OpenTelemetry;
using OpenTelemetry.Logs;
using OpenTelemetry.Resources;
using OpenTelemetry.Trace;

namespace OtelTests;

class Program
{
    static void Main(string[] args)
    {
        IHost host = Host.CreateDefaultBuilder(args)
            .ConfigureServices(services =>
            {
                services.AddOpenTelemetry()
                .ConfigureResource(builder => builder.AddService("as-app"))
                .WithLogging(loggingBuilder =>
                {
                    //loggingBuilder
                    //.AddConsoleExporter()
                    //.AddOtlpExporter(); // Default endpoint is http://localhost:4317
                })
                .UseOtlpExporter();
            })
            .Build();

        ILogger<Program> logger = host.Services.GetRequiredService<ILogger<Program>>();

        for (int logIndex = 0; logIndex < 10; logIndex++)
        {
            logger.LogInformation("This is log entry nr {NR}", logIndex);
        }
        
        host.Run();
    }
}

Project def (used libs/nugets/deps):

<Project Sdk="Microsoft.NET.Sdk">

  <PropertyGroup>
    <OutputType>Exe</OutputType>
    <TargetFramework>net9.0</TargetFramework>
    <ImplicitUsings>enable</ImplicitUsings>
    <Nullable>enable</Nullable>
  </PropertyGroup>

  <ItemGroup>
    <PackageReference Include="Microsoft.Extensions.DependencyInjection" Version="9.0.3" />
    <PackageReference Include="Microsoft.Extensions.Hosting" Version="9.0.3" />
    <PackageReference Include="Microsoft.Extensions.Logging" Version="9.0.3" />
    <PackageReference Include="OpenTelemetry" Version="1.11.2" />
    <PackageReference Include="OpenTelemetry.Exporter.Console" Version="1.11.2" />
    <PackageReference Include="OpenTelemetry.Exporter.OpenTelemetryProtocol" Version="1.11.2" />
    <PackageReference Include="OpenTelemetry.Extensions.Hosting" Version="1.11.2" />
  </ItemGroup>

</Project>

The command to run Aspire Dashboard:

docker run -it -p 18888:18888 -p 4317:18889 -p 4318:18890 -e Dashboard__ResourceServiceClient__AuthMode=Unsecured -e DOTNET_DASHBOARD_UNSECURED_ALLOW_ANONYMOUS=true -e DASHBOARD__OTLP__CORS__ALLOWEDORIGINS='*' -d --name aspire-dashboard mcr.microsoft.com/dotnet/aspire-dashboard:latest

The Dashboard is available here: http://localhost:18888/structuredlogs

Console screenshot:

Image

Aspire log screenshot

Image

stalek71 avatar Mar 19 '25 10:03 stalek71

??

stalek71 avatar Apr 01 '25 17:04 stalek71

You need to call a flush on the tracerprovider to cause the batch to be sent.

martinjt avatar Apr 01 '25 17:04 martinjt

Still nothing. Maybe I'm just doing something wrong? From my point of view, after launching OTEL, flush operation should work automatically (especially upon application shutdown)

class Program
{
    static void Main(string[] args)
    {
        IHost host = Host.CreateDefaultBuilder(args)
            .ConfigureServices(services =>
            {
                services.AddOpenTelemetry()
                .ConfigureResource(builder => builder.AddService("as-app"))
                .WithLogging(loggingBuilder =>
                {
                    //loggingBuilder
                    //.AddConsoleExporter()
                    //.AddOtlpExporter(); // Defaukt endpoint is http://localhost:4317
                })
                .UseOtlpExporter();
            })
            .Build();

        ILogger<Program> logger = host.Services.GetRequiredService<ILogger<Program>>();

        for (int logIndex = 0; logIndex < 10; logIndex++)
        {
            logger.LogInformation("This is log entry nr {NR}", logIndex);
        }

        var tracerProvider = host.Services.GetRequiredService<TracerProvider>();
        tracerProvider.ForceFlush();

        host.Run();
    }
}

stalek71 avatar Apr 01 '25 18:04 stalek71

Do you have the logging level set to include information? Maybe try logging an error?

martinjt avatar Apr 01 '25 18:04 martinjt

I have the default settings, so as far as I remember, it's the Information level. I also checked the Error level, of course, but it didn’t change anything

stalek71 avatar Apr 01 '25 18:04 stalek71

Note that host.Run(); is the point where the OpenTelemetry providers are built. Any logs, spans, or metrics emitted before this line will not be captured.

You can refer to this demo app in the Azure SDK repo for guidance: Azure.Monitor.OpenTelemetry.LiveMetrics.Demo/Program.cs#L36

rajkumar-rangaraj avatar Apr 01 '25 19:04 rajkumar-rangaraj

This code doesn't work as well of course...

using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Hosting;
using Microsoft.Extensions.Logging;
using OpenTelemetry;
using OpenTelemetry.Logs;
using OpenTelemetry.Resources;
using OpenTelemetry.Trace;

namespace OtelTests;

public class SomeHostedService : IHostedService
{
    private readonly ILogger<SomeHostedService> _logger;
    private readonly TracerProvider _tracerProvider;
    public SomeHostedService(ILogger<SomeHostedService> logger, TracerProvider tracerProvider)
    {
        _logger = logger;
        _tracerProvider = tracerProvider;
    }
    public Task StartAsync(CancellationToken cancellationToken)
    {
        _logger.LogInformation("Hosted service started.");
        return Task.CompletedTask;
    }
    public Task StopAsync(CancellationToken cancellationToken)
    {
        _logger.LogInformation("Hosted service stopped.");
        return Task.CompletedTask;
    }
}

class Program
{
    static void Main(string[] args)
    {
        IHost host = Host.CreateDefaultBuilder(args)
            .ConfigureServices(services =>
            {
                services.AddOpenTelemetry()
                .ConfigureResource(builder => builder.AddService("as-app"))
                .WithLogging(loggingBuilder =>
                {
                    //loggingBuilder
                    //.AddConsoleExporter()
                    //.AddOtlpExporter(); // Defaukt endpoint is http://localhost:4317
                })
                .UseOtlpExporter();

               services.AddSingleton<IHostedService, SomeHostedService>();

            })
            .Build();

        ILogger<Program> logger = host.Services.GetRequiredService<ILogger<Program>>();

        for (int logIndex = 0; logIndex < 10; logIndex++)
        {
            logger.LogError("This is log entry nr {NR}", logIndex);
        }

        var tracerProvider = host.Services.GetRequiredService<TracerProvider>();
        tracerProvider.ForceFlush();

        host.Run();
    }
}

Image

stalek71 avatar Apr 16 '25 17:04 stalek71

It looks like this was my mistake (or rather an issue with my computer). When I start the Docker image and run the test program, it tries to establish a connection over IPv6, but for some reason, the Docker image doesn’t map that protocol and only allows connections over IPv4.

That is, when I use localhost as the endpoint address, the connection is attempted via IPv6. However, when I use 127.0.0.1, the program connects to Aspire and I can see entries in the logs.

I still need to investigate why this is happening, because I haven’t blocked IPv6 in Docker Desktop, and explicitly enabling it in the config followed by a restart doesn’t help — communication over IPv6 still doesn’t work.

stalek71 avatar Apr 24 '25 14:04 stalek71

I just found such info: IPv6 is only supported on Docker daemons running on Linux hosts.

https://docs.docker.com/engine/daemon/ipv6/

stalek71 avatar Apr 24 '25 14:04 stalek71

Closing based on previous comment

Kielek avatar Sep 09 '25 10:09 Kielek