newrelic / newrelic-dotnet-agent

The New Relic .NET language agent.
Apache License 2.0
97 stars 61 forks source link

Forward #1324

Closed santanaguy closed 1 year ago

santanaguy commented 1 year ago

Hi team! We started using the automatic forwarding from the agent in our Docker containers (both windows and linux), but we notice that there are some attributes missing or forwarded the wrong way.

Additional info:

Using the Microsoft.Extensions.Logging to log for Console only Our Linux containers have .net 7 Our Windows containers have .Net Framework 4.8 Agent version is 10.4 (most recent)

Things we tried:

Here is code from a sample application where we have the same problem:

using Microsoft.AspNetCore.Identity;
using Microsoft.EntityFrameworkCore;
using WebApplication1.Data;

var builder = WebApplication.CreateBuilder(args);
// Add services to the container.
var connectionString = builder.Configuration.GetConnectionString("DefaultConnection");
builder.Services.AddDbContext<ApplicationDbContext>(options =>
    options.UseSqlServer(connectionString));
builder.Services.AddDatabaseDeveloperPageExceptionFilter();

builder.Services.AddDefaultIdentity<IdentityUser>(options => options.SignIn.RequireConfirmedAccount = true)
    .AddEntityFrameworkStores<ApplicationDbContext>();
builder.Services.AddControllersWithViews();

var app = builder.Build();

// Configure the HTTP request pipeline.
if (app.Environment.IsDevelopment())
{
    app.UseMigrationsEndPoint();
}
else
{
    app.UseExceptionHandler("/Home/Error");
    // The default HSTS value is 30 days. You may want to change this for production scenarios, see https://aka.ms/aspnetcore-hsts.
    app.UseHsts();
}

app.UseHttpsRedirection();
app.UseStaticFiles();

app.UseRouting();

app.UseAuthentication();
app.UseAuthorization();

app.MapControllerRoute(
    name: "default",
    pattern: "{controller=Home}/{action=Index}/{id?}");
app.MapRazorPages();

app.Run();

FROM mcr.microsoft.com/dotnet/aspnet:6.0 AS base
WORKDIR /app
EXPOSE 80
EXPOSE 443

FROM mcr.microsoft.com/dotnet/sdk:6.0 AS build
WORKDIR /src
COPY ["WebApplication1.csproj", "."]
RUN dotnet restore "./WebApplication1.csproj"
COPY . .
WORKDIR "/src/."
RUN dotnet build "WebApplication1.csproj" -c Release -o /app/build

FROM build AS publish
RUN dotnet publish "WebApplication1.csproj" -c Release -o /app/publish

FROM base AS final

# Install the agent
RUN apt-get update && apt-get install -y wget ca-certificates gnupg \
&& echo 'deb http://apt.newrelic.com/debian/ newrelic non-free' | tee /etc/apt/sources.list.d/newrelic.list \
&& wget https://download.newrelic.com/548C16BF.gpg \
&& apt-key add 548C16BF.gpg \
&& apt-get update \
&& apt-get install -y newrelic-dotnet-agent \
&& rm -rf /var/lib/apt/lists/*

# Enable the agent
ENV CORECLR_ENABLE_PROFILING=1 \
CORECLR_PROFILER={36032161-FFC0-4B61-B559-F6C5D41BAE5A} \
CORECLR_NEWRELIC_HOME=/usr/local/newrelic-dotnet-agent \
CORECLR_PROFILER_PATH=/usr/local/newrelic-dotnet-agent/libNewRelicProfiler.so \
NEW_RELIC_LICENSE_KEY=<omitted> \
NEW_RELIC_APP_NAME=My-App2 \
NEW_RELIC_APPLICATION_LOGGING_FORWARDING_CONTEXT_DATA_ENABLED=true

WORKDIR /app
COPY --from=publish /app/publish .

ENTRYPOINT ["dotnet", "WebApplication1.dll"]

Controller code where logger gets used

public IActionResult Privacy()
{
   _logger.LogTrace($"Privacy Debug Message produced at {DateTime.UtcNow}");
    _logger.LogDebug ($"Privacy Debug Message produced at {DateTime.UtcNow}");
    _logger.LogInformation($"Privacy Information Message produced at {DateTime.UtcNow}");
    _logger.LogWarning ($"Privacy Warning Message produced at {DateTime.UtcNow}");
    _logger.LogError ($"Privacy Error Message produced at {DateTime.UtcNow}");
    _logger.LogCritical ($"Privacy Critical Message produced at {DateTime.UtcNow}");
    throw new NullReferenceException();
    return View();
}

Some logging we see on the console:

image

How it shows in the logs:

image

image

As you can see, no logger information or anything. I get the feeling we are getting something basic wrong, but its not clear what.

Can you help with this?

workato-integration[bot] commented 1 year ago

https://issues.newrelic.com/browse/NEWRELIC-5844

chynesNR commented 1 year ago

Hi @santanaguy - sorry to hear you're having trouble with your log data! I'd like to go over your concerns:

Info level is forwarded as INFORMATION and is not shown with a blue color in the Logging UI

The log level is named however the logger names it internally, and for MEL this is "Information", rather than "Info". I believe this is working as intended.

Could you elaborate on the color being wrong? In the screenshot you've attached it looks like INFORMATION is already blue.

There is no logger name information forwarded at all No thread number, etc etc

With the new context data functionality, we do not include anything automatically. While we could add things like Thread ID or logger name, we do not at this time, as each user may want something different. What we have done is add the ability to pull in any context data already in the logger. This is what the ...CONTEXT_DATA_ENABLED environment variable does.

In Microsoft.Extensions.Logging, this data is captured in Scopes: https://learn.microsoft.com/en-us/dotnet/core/extensions/logging?tabs=command-line#log-scopes

In Serilog, these are known as Properties.

Any context data that you want forwarded from your logs needs to be added to the logger via the mechanism that logger uses. I can provide some examples if that would help.

Does that make sense? We could probably be clearer about this in our documentation.

santanaguy commented 1 year ago

Hello @chynesNR

Thanks for the quick and detailed answer. About the color, I meant the blue square that generally shows up in INFO level

image

Check the image above: there is no square for INFORMATION, but there is a blue one for INFO. This would allow us to hide the level column relying only on the color.

As per the context, I understand now the point of it and how it works, but then I'm left wondering how we can achieve our purpose, which is to attach some information (eg: the environment name) to all the logs captured. In a VM we would configure the forwarder to do it for us, but how can we achieve the same now with automatic forwarding?

I think capturing the thread number and the logger name would be very useful, but it makes sense to be optional. If we use the Serilog log enrichers would this be included? The problem I see with using the scopes/properties is that suddenly we have to spread that information everywhere in code...

You're right about the fact that the docs got me confused, maybe a little improvement there would make it more clear :)

chynesNR commented 1 year ago

Hi @santanaguy - thanks for the additional information! You're right, it looks like there is a UI bug where INFO and INFORMATION are not treated the same. But it looks like you can still click on where the square would be, or on the word INFORMATION itself, and apply a filter that way. If you give that a try, let me know if that's what you're looking for. It doesn't look like there's an easy way to apply a global scope in Microsoft Extensions Logging, so that might not be a good fit. Serilog enrichers should be exactly what you're looking for, though. You can add properties there and the .NET Agent will pick them up.

santanaguy commented 1 year ago

Hi @chynesNR Yup, filtering by info on the UI does work correcly, the only thing was that the color does not show up correctly, which is a minor bug of course.

We will eventually test the Serilog enricher. It seems like I have my answers, thank you!