How can you correlate logs with APM?

I have an application that will write logs to elasticsearch using serilog. I configured the APM server using docker-compose. Once I start the application up and perform an operation (navigate through pages in the browser), then close the application. Those logs are then recorded to elasticsearch. I came across this article that talks about correlating logs with APM. I selected a few steps to follow since I am not using python in this application, and noticed that there are transactions that are inside of APM.

How can I tie these logs together is there a unique variable/id/key that will tie all the logs that were recorded in one single transaction (when I started the application, performed operations, then closed the application)?

When I looked into each of the transactions, I noticed that they have a transcation_id and a trace_id. But, they are changing per each operation that I am performing. I am wanting to know if it is possible and if it is, how can I gather all the logs that pertain to that single transaction? For instance, if I query by a single id, then all of those logs will be returned.

docker-compose.yml

version: '2.2'
services:
  apm-server:
    image: docker.elastic.co/apm/apm-server:7.13.0
    depends_on:
      elasticsearch:
        condition: service_healthy
      kibana:
        condition: service_healthy
    cap_add: ["CHOWN", "DAC_OVERRIDE", "SETGID", "SETUID"]
    cap_drop: ["ALL"]
    ports:
    - 8200:8200
    networks:
    - elastic
    command: >
       apm-server -e
         -E apm-server.rum.enabled=true
         -E setup.kibana.host=kibana:5601
         -E setup.template.settings.index.number_of_replicas=0
         -E apm-server.kibana.enabled=true
         -E apm-server.kibana.host=kibana:5601
         -E output.elasticsearch.hosts=["elasticsearch:9200"]
    healthcheck:
      interval: 10s
      retries: 12
      test: curl --write-out 'HTTP %{http_code}' --fail --silent --output /dev/null http://localhost:8200/

  elasticsearch:
    image: docker.elastic.co/elasticsearch/elasticsearch:7.13.0
    environment:
    - bootstrap.memory_lock=true
    - cluster.name=docker-cluster
    - cluster.routing.allocation.disk.threshold_enabled=false
    - discovery.type=single-node
    - ES_JAVA_OPTS=-XX:UseAVX=2 -Xms1g -Xmx1g
    ulimits:
      memlock:
        hard: -1
        soft: -1
    volumes:
    - esdata:/usr/share/elasticsearch/data
    ports:
    - 9200:9200
    networks:
    - elastic
    healthcheck:
      interval: 20s
      retries: 10
      test: curl -s http://localhost:9200/_cluster/health | grep -vq '"status":"red"'

  kibana:
    image: docker.elastic.co/kibana/kibana:7.13.0
    depends_on:
      elasticsearch:
        condition: service_healthy
    environment:
      ELASTICSEARCH_URL: http://elasticsearch:9200
      ELASTICSEARCH_HOSTS: http://elasticsearch:9200
    ports:
    - 5601:5601
    networks:
    - elastic
    healthcheck:
      interval: 10s
      retries: 20
      test: curl --write-out 'HTTP %{http_code}' --fail --silent --output /dev/null http://localhost:5601/api/status

volumes:
  esdata:
    driver: local

networks:
  elastic:
    driver: bridge

I ran into this [documentation] (Serilog | APM .NET Agent Reference [1.10] | Elastic) for Elastic.Apm.SerilogEnricher , I went ahead and included it to my Startup.cs file and my Program.cs file.

Startup.cs:

    namespace CustomerSimulatorApp
    {
        public class Startup
        {
            public Startup(IConfiguration configuration)
            {
                Configuration = configuration;

                var logger = new LoggerConfiguration()
                    .Enrich.WithElasticApmCorrelationInfo()
                    .WriteTo.Console(outputTemplate: "[{ElasticApmTraceId} {ElasticApmTransactionId} {Message:lj} {NewLine}{Exception}")
                    .CreateLogger();
            }

            public IConfiguration Configuration { get; }

            // This method gets called by the runtime. Use this method to add services to the container.
            public void ConfigureServices(IServiceCollection services)
            {
                services.AddControllersWithViews();

                // create a new node instance
                var node = new Uri("http://localhost:9200");
                // settings instance for the node
                var settings = new ConnectionSettings(node);
                settings.DefaultFieldNameInferrer(p => p);

                services.AddSingleton<IElasticClient>(new ElasticClient(settings));
            }

            // This method gets called by the runtime. Use this method to configure the HTTP request pipeline.
            public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
            {
                app.UseAllElasticApm(Configuration);

                if (env.IsDevelopment())
                {
                    app.UseDeveloperExceptionPage();
                }
                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.UseAuthorization();

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

Program.cs:

    namespace CustomerSimulatorApp
    {
        public class Program
        {
            public static void Main(string[] args)
            {
                CreateHostBuilder(args).Build().Run();
            }


            public static IHostBuilder CreateHostBuilder(string[] args) =>
                Host.CreateDefaultBuilder(args)
                    .UseSerilog((context, configuration) =>
                    {
                        configuration.Enrich.FromLogContext()
                            .Enrich.WithElasticApmCorrelationInfo()
                            .Enrich.WithMachineName()
                            .WriteTo.Console()
                            .WriteTo.Elasticsearch(new ElasticsearchSinkOptions(new Uri(context.Configuration["ElasticConfiguration:Uri"]))
                            {
                                IndexFormat = $"{context.Configuration["ApplicationName"]}-logs-{context.HostingEnvironment.EnvironmentName?.ToLower().Replace(".", "-")}-{DateTime.UtcNow:yyyy-MM}",
                                AutoRegisterTemplate = true
                            })
                            .Enrich.WithProperty("Environment", context.HostingEnvironment.EnvironmentName)
                            .ReadFrom.Configuration(context.Configuration);
                    })
                    .ConfigureWebHostDefaults(webBuilder =>
                    {
                        webBuilder.UseStartup<Startup>();
                    })
                    .UseAllElasticApm();
        }
    }

This is what I see in my console...

However, when I run the program, I get different transaction id's and trace id's. Is there something I am doing incorrectly when I implement the serilog to correlate my logs from the documentation that I read?

Hi @NoviceESCoder,

yeah, you can do this. The APM traces and the logs are connected through the traceid field - this will be different for each trace.

One issue I see in your code is that the .NET APM agent is added twice - you have it in Startup.cs: on line app.UseAllElasticApm(Configuration); in the Configure method and in Program.cs: on IHostbuilder with .UseAllElasticApm(); as well. You can remove it from one of those - I'd suggest keepeing the one from Program.cs and remove from Startup.cs.

Once this works you should be able to jump from APM traces to logs with this button:

And on the Log UI there is a similar one from jumping from logs to APM traces. One thing to keep in mind here is that this integration only works for log lines that are captured during an active transaction (e.g. in case of ASP.NET Core during an HTTP request).

Hi @GregKalapos

Ok good to know, thank you. So lets say, when I run the program and the browser starts up it takes me to the home page. I then click on a button that will redirect me to another page. On that new page, there is a button that I click on that will redirect me to another page. On that new page, there is another button that redirects me to a page that no longer has buttons. Then I close out the browser, stopping the program doing a single transaction. All of those logs that are written to elasticsearch, the traceid will always be different from what you are saying correct? So if I wanted to lets say do a query search, how would I be able to extract all of those logs that were recorded as I went through the browser? Because ultimately what I want is whenever I open my browser and perform the operations, for it to be stored as a single session id so when I pull up that id those logs for that session id will populate, so I can see if lets say there was an error in it I can go into it and figure out what caused it.

Thank you for the heads up on that .NET APM agent being added twice!

Thanks for sharing this information with me!

That's correct.

Because ultimately what I want is whenever I open my browser and perform the operations, for it to be stored as a single session id so when I pull up that id those logs for that session id will populate, so I can see if lets say there was an error in it I can go into it and figure out what caused it.

I now see what your goal is - but unfortunately thee is a bit of a mismatch between your goal and what this feature offers.

One key point of this feature is to correlate logs and traces in a multi service environment. So let's say you have 3 services that call each other: A -> B - C - you could add the setup you pasted above to all of those, and with that the traceid will be the same on the 3 service for any given call. If let's say C fails, you can see the APM traces and the logs through all 3 services.

Now - you don't really need any of this if you only have 1 service - in that case all you need to do is to attach the session id to the logs and filter based on session id. Unfortunately I don't know what serilog offers to attach data to logs, but that should be doable.

@GregKalapos:

That's correct.

Ok, I gotcha thanks for clarifying this for me.

One key point of this feature is to correlate logs and traces in a multi service environment. So let's say you have 3 services that call each other: A -> B - C - you could add the setup you pasted above to all of those, and with that the traceid will be the same on the 3 service for any given call. If let's say C fails, you can see the APM traces and the logs through all 3 services.

I see, so in regards to what you mentioned... if I would want to do this, I would need to add the .Enrich.WithElasticApmCorrelationInfo() so that way I can have the same traceid on all 3 services for any given call?

So for instance my current controllers are:

HomeController

namespace CustomerSimulatorApp.Controllers
{
    public class HomeController : Controller
    {
        private readonly ILogger<HomeController> _logger;

        public HomeController(ILogger<HomeController> logger)
        {
            _logger = logger;
        }

        public IActionResult Index()
        {

            return View();
        }
    }
}

My next controller would be SecondController.cs

namespace CustomerSimulatorApp.Controllers
{
    public class SecondController : Controller
    {

        private readonly ILogger<SecondController> _logger;

        public SecondController(ILogger<SecondController> logger)
        {
            _logger = logger;
        }

        public IActionResult SecIndex()
        { 
            return View();
        }

        [HttpPost]
        public IActionResult SecIndex(TextInput form)
        {
            try
            {
                if (ModelState.IsValid)
                    return RedirectToAction("FinalIndex", "Final");
                else
                    throw new Exception("Looks like you did not type something!");
             
            }
            catch(Exception ex)
            {
                _logger.LogError(ex, "Empty textfield!");
                return RedirectToAction("FinalIndex", "Final");
            }
        }     
    }
}

My next controller is CompletedController.cs

namespace CustomerSimulatorApp.Controllers
{
    public class CompletedController : Controller
    {
        public IActionResult CompletedIndex()
        {
            return View();
        }
    }
}

So, I would need to add the .Enrich.WithElasticApmCorrelationInfo() to each of those controllers? Is there a specific area in the controllers that this needs to be in, in order for it to work as it should?

Hi @GregKalapos

So I went ahead and attempted to implement what you mention about if I have 3 services that call each other A -> B -> C and the traceid will be the same on the 3 service for any given call. What I did was include var logr = new LoggerConfiguration() .Enrich.WithElasticApmCorrelationInfo(); to all of my controllers but it still did not work. Because as I went from page A -> C the traceid was all completely different. Did I not set it up correctly?

HomeController.cs

public class HomeController : Controller
    {
        private readonly ILogger<HomeController> _logger;

        public HomeController(ILogger<HomeController> logger)
        {
            _logger = logger;

            var logr = new LoggerConfiguration()
                .Enrich.WithElasticApmCorrelationInfo();
        }

        public IActionResult Index()
        {

            return View();
        }

    }

SecondController.cs

 public class SecondController : Controller
    {

        private readonly ILogger<SecondController> _logger;

        public SecondController(ILogger<SecondController> logger)
        {
            _logger = logger;
            var logr = new LoggerConfiguration()
                .Enrich.WithElasticApmCorrelationInfo();
        }

        public IActionResult SecIndex()
        { 
            return View();
        }

        [HttpPost]
        public IActionResult SecIndex(TextInput form)
        {
            try
            {
                if (ModelState.IsValid)
                    return RedirectToAction("FinalIndex", "Final");
                else
                    throw new Exception("Looks like you did not type something!");
             
            }
            catch(Exception ex)
            {
                _logger.LogError(ex, "Empty textfield!");
                return RedirectToAction("FinalIndex", "Final");
            }
        }     
    }

last controller:

 public class CompletedController : Controller
    {
        private readonly ILogger<CompletedController> _logger;

        public CompletedController(ILogger<CompletedController> logger)
        {
            _logger = logger;
            var logr = new LoggerConfiguration()
                .Enrich.WithElasticApmCorrelationInfo();
        }

        public IActionResult CompletedIndex()
        {
            return View();
        }
    }

Any advice on what I did incorrectly to implement your suggestion?

Hey @NoviceESCoder,

with "multiple services" I mean multiple processes - or in other words multiple ASP.NET Core processes talking calling each other.

When you use return RedirectToAction the original HTTP call returns with status code 302 and the browser creates a new HTTP call - so technically the 2 calls are not related. In my A -> B -> C example I talk about different services calling each other - so in your 1. servicer you'd have an outgoing HTTP call to another service (which could also run on a different machine).

If you want to test it with 1 process, then 1 thing you could do is to just do an outgoing HTTP request to another controller with HttpClient - that'd be a simulation where you'd see distributed tracing and log correlation working. But again, the main point is to do this across multiple services (processes) and correlation those.

Regarding where to put the .Enrich.WithElasticApmCorrelationInfo() call:

You should configure the logger only one during the startup and not in the controller - Look at the serilog ASP.NET Core instructions here - just do the same and call .Enrich.WithElasticApmCorrelationInfo() on the LoggerConfiguration from the code-snippet. With that you configure the logger once during startup (including adding the APM enricher).

I understand it now! Thank you for the clarification and help!