Correlation logs are not reported in background service

[Nicolas_Rey]

Hi,

Thanks to @GregKalapos I finally managed to listen to Http ougoing calls in an Asp .net core Background service and report them in APM.

But now I still have a point :
where can I found my correlated logs (with Serilog) in APM Kibana UI ?

Here is my appsettings.json

 "Serilog": {
    "Using": [],
    "MinimumLevel": {
      "Default": "Information",
      "Override": {
        "Microsoft": "Warning",
        "System": "Information",
        "Elastic": "Verbose"
      }
    },
"WriteTo": [
      {
        "Name": "Console"
      }
    ],
    "Enrich": [
      "FromLogContext",
      "WithMachineName",
      "WithProcessId",
      "WithThreadId"
    ],
    "Properties": {
      "ApplicationName": "myMicroservice"
    }
  },
  "ElasticApm": {
    "ServerUrls": "http://apm:8200"
  }

My Serilog logger instance creator

            return new LoggerConfiguration()
            .ReadFrom.Configuration(config)
            .Enrich.WithElasticApmCorrelationInfo()
            .WriteTo.Elasticsearch(new ElasticsearchSinkOptions(new Uri("http://elasticsearch:9200/"))
            {
                AutoRegisterTemplate = true,
                AutoRegisterTemplateVersion = AutoRegisterTemplateVersion.ESv7,
                FailureCallback = e => Console.WriteLine("Unable to submit event " + e.MessageTemplate),
                EmitEventFailure = EmitEventFailureHandling.WriteToSelfLog |
                                        EmitEventFailureHandling.WriteToFailureSink |
                                        EmitEventFailureHandling.RaiseCallback,
                CustomFormatter = new EcsTextFormatter()
            })
            .WriteTo.OpenTracing()
            .CreateLogger();

I'm using the nuget packages

Elastic.Apm.NetCoreAll v1.6.1
Elastic.Apm.SerilogEnricher v1.5.1
Elastic.CommonSchema.Serilog v1.5.1

My docker-compose.yml file

version: '3.4'

services:

  myMicroservice:
    image: ${DOCKER_REGISTRY-}myMicroservice
    container_name: myMicroservice
    build:
      context: .
      dockerfile: src/myMicroservice/src/Dockerfile
    depends_on:
      - elasticsearch

  elasticsearch:
    image: docker.elastic.co/elasticsearch/elasticsearch:7.9.2
    container_name: elasticsearch
    environment:
      - discovery.type=single-node
      - cluster.name=docker-cluster
      - bootstrap.memory_lock=true
      - "ES_JAVA_OPTS=-Xms4g -Xmx4g"
    ulimits:
      memlock:
        soft: -1
        hard: -1
    ports:
      - "9200:9200"
    volumes:
      - ./volumes/elasticsearch:/usr/share/elasticsearch/data

  apm:
    image: docker.elastic.co/apm/apm-server:7.9.2
    container_name: apm
    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"]
    ports:
      - "8200:8200"
    expose:
      - "8200"
    links:
      - elasticsearch
    depends_on:
      - elasticsearch
      - kibana

  kibana:
    image: docker.elastic.co/kibana/kibana:7.9.2
    container_name: kibana
    environment:
      - ELASTICSEARCH_URL=http://elasticsearch:9200
    ports:
      - "5601:5601"
    depends_on:
      - elasticsearch

My async Task called in a Background service ExecuteAsync method

        public async Task Test()
        {
            await Agent.Tracer
            .CaptureTransaction("TransactionTest", ApiConstants.TypeRequest, async (t) =>
            {
                _logger.LogInformation($"First Test log");

                await t.CaptureSpan("GetTestSpan1", "ElasticSearch", async span =>
                {
                    _logger.LogInformation($"Test log 1");
                    _logger.LogWarning($"Test log 1");
                    _logger.LogError($"Test log 1");
                    _logger.LogCritical($"Test log 1");
                    await Task.FromResult(true);
                });

                await t.CaptureSpan("GetTestSpan2", "ElasticSearch", async span =>
                {
                    _logger.LogInformation($"Test log 2");
                    _logger.LogWarning($"Test log 2");
                    _logger.LogError($"Test log 2");
                    _logger.LogCritical($"Test log 2");
                    await Task.FromResult(true);
                });

                await t.CaptureSpan("GetTestSpan3", "ElasticSearch", async span =>
                {
                    _logger.LogInformation($"Test log 3");
                    _logger.LogWarning($"Test log 3");
                    _logger.LogError($"Test log 3");
                    _logger.LogCritical($"Test log 3");
                    await Task.FromResult(true);
                });
            });
        }

And finally the output in APM

But where ever I click I'm not able to see any of my logs, where am I supposed to see them ? I guessed on clicking on the span within a transaction I could see them, could someone help on that ?

And finally the full Microservice + APM logs in verbose mode
APM missing correlated logs

[Nicolas_Rey]

Considering Serilog logger produces an index logstash-YYYY.MM.DD I managed to display correlated logs addind the following in Log indices of log Settings

Then using the Trace Logs from the Action link

I can see the logs

Is it the correct way to display logs from Serilog ?

Many thanks

[GregKalapos]

@Nicolas_Rey sorry for the late reply - yes your solution is correct and that's the intended way this should work.

Basically what happens here is that with .Enrich.WithElasticApmCorrelationInfo() each time you log something, an enricher will tag the specific log line with the current trace id. The "Actions" -> "Trace logs" button on the APM UI will jump to the logs UI showing only the logs from the given trace for all services that participated in the trace. Similarly there is also a button on the logs UI which lets you jump to APM in case the log was tagged with a trace id.

Maybe one last note - but probably you already figured this out: this works only when there is an active transaction when the log line is created.

[Nicolas_Rey]

@GregKalapos

Many thanks for your reply and yout high availability for the community, it's awesome!

Maybe an end to end tutorial for this kind of basics needs may be useful to other people, or maybe it already exists and I missed it ?