Agent doesn't start : unable to retrieve connection to Kibana (.net core 3.1)

Hi,

I can't make the .net core Agent work for APM Server, I get the following error

[08:32:13 ERR] {CentralConfigFetcher} Exception was thrown while fetching configuration from APM Server and parsing it. ETag: `<null>'. URL: `http://apm:8200/config/v1/agents?service.name=ITF_Microservices_CatalogSynchronizer&service.environment=Development'. Apm Server base URL: `http://apm:8200/'. WaitInterval: 5m. dbgIterationsCount: 1.
+-> Request:
    Method: GET, RequestUri: 'http://apm:8200/config/v1/agents?service.name=ITF_Microservices_CatalogSynchronizer&service.environment=Development', Version: 1.1, Content: <null>, Headers:
    {
      User-Agent: elasticapm-dotnet/1.6.1
      User-Agent: System.Net.Http/4.700.20.47203
      User-Agent: .NET_Core/3.1.9
    }
+-> Response:
    StatusCode: 503, ReasonPhrase: 'Service Unavailable', Version: 1.1, Content: System.Net.Http.HttpConnectionResponseContent, Headers:
    {
      Cache-Control: must-revalidate, max-age=300
      X-Content-Type-Options: nosniff
      Date: Mon, 19 Oct 2020 08:32:13 GMT
      Content-Type: text/plain; charset=utf-8
      Content-Length: 52
    }
+-> Response body [length: 52]:
    {"error":"unable to retrieve connection to Kibana"}

Elastic.Apm.BackendComm.CentralConfig.CentralConfigFetcher+FailedToFetchConfigException: HTTP status code is Service Unavailable (503) which most likely means that APM Server supports the central configuration endpoint and Kibana connection is enabled, but Kibana connection is unavailable
   at Elastic.Apm.BackendComm.CentralConfig.CentralConfigResponseParser.InterpretResponseStatusCode(HttpResponseMessage httpResponse, WaitInfoS waitInfo)
   at Elastic.Apm.BackendComm.CentralConfig.CentralConfigResponseParser.ParseHttpResponse(HttpResponseMessage httpResponse, String httpResponseBody)
   at Elastic.Apm.BackendComm.CentralConfig.CentralConfigFetcher.WorkLoopIteration()

I use a docker-compose 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

And all my containers are up

 docker ps
CONTAINER ID        IMAGE                                                 COMMAND                  CREATED             STATUS              PORTS                                                NAMES
0c5ad063e58d        docker.elastic.co/apm/apm-server:7.9.2                "/usr/local/bin/dock…"   10 minutes ago      Up 10 minutes       0.0.0.0:8200->8200/tcp                               apm
ca75710de858        mymicroservice:dev                                    "tail -f /dev/null"      11 minutes ago      Up 10 minutes       443/tcp, 0.0.0.0:60713->80/tcp                       mymicroservice
2d1b8eaa89fe        docker.elastic.co/kibana/kibana:7.9.2                 "/usr/local/bin/dumb…"   11 minutes ago      Up 10 minutes       0.0.0.0:5601->5601/tcp                               kibana
1ab4e7260aec        docker.elastic.co/elasticsearch/elasticsearch:7.9.2   "/tini -- /usr/local…"   11 minutes ago      Up 11 minutes       0.0.0.0:9200->9200/tcp, 9300/tcp                     elasticsearch

and Kibana does communicate correclty with Elk (I can use the UI to look at my collections and so on). But the APM part is still failing.

I'm using the nuget packages
Elastic.Apm.NetCoreAll v1.6.1
Elastic.Apm.SerilogEnricher v1.5.1
Elastic.CommonSchema.Serilog v1.5.1

Here is how I create my logger

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

And my appsettings.json file

 "ElasticApm": {
   "ServerUrls": "http://apm:8200",
   "CaptureBody": "all"
 }

What am I doing wrong ?
Thank you

Hi @Nicolas_Rey,

The error you pasted from the agent log only says that central config is not enabled - you don't need that for the agent to run, so I'd suggest to ignore that for now.

I see (based on the LoggerConfiguration you pasted) that you turned on log correlation - what it does is that logs sent to Elasticsearch will be correlated to traces captured by the .NET APM Agent - but it does not start the agent itself.

For enabling the agent we have some docs here - I linked the one for ASP.NET Core, but there are more .NET flavors covered on that page.

Hi @GregKalapos

Sorry for the incomplete code, I did start the agent in Configure method with

app.UseAllElasticApm(Configuration);

The problem I got was linked to Elastic itself when I activated the Debug log level, too much logs wer sent to the container which locked the the disk in read mode :

[cluster_block_exception] index [.async-search] blocked by: [TOO_MANY_REQUESTS/12/disk usage exceeded flood-stage watermark, index has read-only-allow-delete block];

Solved with

curl -XPUT -H "Content-Type: application/json" http://localhost:9200/_cluster/settings -d '{ "transient": { "cluster.routing.allocation.disk.threshold_enabled": false } }'
curl -XPUT -H "Content-Type: application/json" http://localhost:9200/_all/_settings -d '{"index.blocks.read_only_allow_delete": null}'

Now I have my MS visible in APM, but I can't see any transaction, nor log


but Metrics are sent to APM

Did I miss something ?

Thanks

@Nicolas_Rey ok, so by adding app.UseAllElasticApm(Configuration); to the app it should work - I soo no wrong config in the snippets you pasted.

Is there any way to collect more agent logs? Maybe instead of Debug, try Warning first - if this is a connection issue then you'd see those already on Warning level with significantly less line printed, so hopefully it won't cause any issues.

Also to make sure I have the full picture: So this is an ASP.NET Core app and you have load on the app, right?

@GregKalapos

Yes it's an Asp .net core (3.1) app, for the log level I use Serilog nested log level config, maybe it's a problem ?

See my complete appsettings.json

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

I do expect more logs as the I do log some business logic and all http calls are logged as well (by the framework itself I guess), see some example of output I got in my console (I didn't retrieve any of if in APM)

[09:53:47 INF] Synchronization is starting
[09:53:47 INF] Start processing HTTP request POST https://login.microsoftonline.com/xxxxxxx/oauth2/token
[09:53:47 INF] Sending HTTP request POST https://login.microsoftonline.com/xxxxxxx/oauth2/token
[09:53:47 INF] {CentralConfigFetcher} Updating ConfigStore. New central configuration: [ETag: `"-"']{}
[09:53:47 INF] {ConfigStore} Replaced current snapshot. Old: local + central (ETag: `"-"'). New: local + central (ETag: `"-"').
[09:53:48 INF] Received HTTP response after 403.1225ms - OK
[09:53:48 INF] End processing HTTP request after 493.119ms - OK
[09:53:48 INF] Start processing HTTP request GET https://myUrl/data/myEntity/$count/?$select=field1,field2
[09:53:48 INF] Sending HTTP request GET https://myUrl/data/myEntity/$count/?$select=field1,field2
[09:53:48 INF] Received HTTP response after 482.7925ms - OK
[09:53:48 INF] End processing HTTP request after 483.9661ms - OK

Here are the last logs of the apm container

2020-10-19T09:32:25.271Z INFO [pipelines] pipeline/register.go:56 Registered Ingest Pipelines successfully.

2020-10-19T09:32:25.271Z INFO [publisher_pipeline_output] pipeline/output.go:151 Connection to backoff(elasticsearch(http://elasticsearch:9200)) established

2020-10-19T09:32:25.271Z INFO [publisher] pipeline/retry.go:219 retryer: send unwait signal to consumer

2020-10-19T09:32:25.272Z INFO [publisher] pipeline/retry.go:223 done

2020-10-19T09:35:13.469Z INFO [request] middleware/log_middleware.go:97 request ok {"request_id": "5d15d5ae-59c7-4ede-a9b0-3c29fdd41ad7", "method": "GET", "URL": "/config/v1/agents?service.name=myMicroservice&service.environment=Development", "content_length": 0, "remote_address": "172.22.0.6", "user-agent": "elasticapm-dotnet/1.6.1 System.Net.Http/4.700.20.47203 .NET_Core/3.1.9", "response_code": 200}

2020-10-19T09:35:44.335Z INFO [request] middleware/log_middleware.go:97 not modified {"request_id": "428af366-838a-4e6d-8ade-4de6d38aa57d", "method": "GET", "URL": "/config/v1/agents?service.name=myMicroservice&service.environment=Development", "content_length": 0, "remote_address": "172.22.0.6", "user-agent": "elasticapm-dotnet/1.6.1 System.Net.Http/4.700.20.47203 .NET_Core/3.1.9", "response_code": 304}

2020-10-19T09:35:53.664Z INFO [request] middleware/log_middleware.go:97 request accepted {"request_id": "f7f91cec-7860-43ea-a57d-27bbdce6d5c4", "method": "POST", "URL": "/intake/v2/events", "content_length": 1151, "remote_address": "172.22.0.6", "user-agent": "elasticapm-dotnet/1.6.1 System.Net.Http/4.700.20.47203 .NET_Core/3.1.9", "response_code": 202}

2020-10-19T09:36:13.670Z INFO [request] middleware/log_middleware.go:97 request accepted {"request_id": "6393a404-edde-4f2a-aaf3-12a3c9e3540d", "method": "POST", "URL": "/intake/v2/events", "content_length": 1153, "remote_address": "172.22.0.6", "user-agent": "elasticapm-dotnet/1.6.1 System.Net.Http/4.700.20.47203 .NET_Core/3.1.9", "response_code": 202}

2020-10-19T09:36:14.462Z INFO [request] middleware/log_middleware.go:97 not modified {"request_id": "99bac600-9090-43fe-ae14-cd3cd8e5bff3", "method": "GET", "URL": "/config/v1/agents?service.name=myMicroservice&service.environment=Development", "content_length": 0, "remote_address": "172.22.0.6", "user-agent": "elasticapm-dotnet/1.6.1 System.Net.Http/4.700.20.47203 .NET_Core/3.1.9", "response_code": 304}

2020-10-19T09:36:43.729Z INFO [request] middleware/log_middleware.go:97 request accepted {"request_id": "fb0f609a-09aa-4dfd-86eb-ce406dc445bb", "method": "POST", "URL": "/intake/v2/events", "content_length": 1154, "remote_address": "172.22.0.6", "user-agent": "elasticapm-dotnet/1.6.1 System.Net.Http/4.700.20.47203 .NET_Core/3.1.9", "response_code": 202}

2020-10-19T09:36:44.547Z INFO [request] middleware/log_middleware.go:97 not modified {"request_id": "189c310a-e47d-44ec-9291-959ae28d17e1", "method": "GET", "URL": "/config/v1/agents?service.name=myMicroservice&service.environment=Development", "content_length": 0, "remote_address": "172.22.0.6", "user-agent": "elasticapm-dotnet/1.6.1 System.Net.Http/4.700.20.47203 .NET_Core/3.1.9", "response_code": 304}

2020-10-19T09:37:13.781Z INFO [request] middleware/log_middleware.go:97 request accepted {"request_id": "de0d6375-e435-4023-a9f6-a47eadca0acb", "method": "POST", "URL": "/intake/v2/events", "content_length": 1163, "remote_address": "172.22.0.6", "user-agent": "elasticapm-dotnet/1.6.1 System.Net.Http/4.700.20.47203 .NET_Core/3.1.9", "response_code": 202}

2020-10-19T09:37:14.756Z INFO [request] middleware/log_middleware.go:97 not modified {"request_id": "efc64fa0-a82b-4e96-aeaa-883122038029", "method": "GET", "URL": "/config/v1/agents?service.name=myMicroservice&service.environment=Development", "content_length": 0, "remote_address": "172.22.0.6", "user-agent": "elasticapm-dotnet/1.6.1 System.Net.Http/4.700.20.47203 .NET_Core/3.1.9", "response_code": 304}

2020-10-19T09:37:43.814Z INFO [request] middleware/log_middleware.go:97 request accepted {"request_id": "dc058d00-2cdf-4409-95c4-bddb43a8e09d", "method": "POST", "URL": "/intake/v2/events", "content_length": 1161, "remote_address": "172.22.0.6", "user-agent": "elasticapm-dotnet/1.6.1 System.Net.Http/4.700.20.47203 .NET_Core/3.1.9", "response_code": 202}

2020-10-19T09:37:44.927Z INFO [request] middleware/log_middleware.go:97 not modified {"request_id": "b0313126-4436-498a-9023-4411a40277c4", "method": "GET", "URL": "/config/v1/agents?service.name=myMicroservice&service.environment=Development", "content_length": 0, "remote_address": "172.22.0.6", "user-agent": "elasticapm-dotnet/1.6.1 System.Net.Http/4.700.20.47203 .NET_Core/3.1.9", "response_code": 304}

2020-10-19T09:53:47.637Z INFO [request] middleware/log_middleware.go:97 request ok {"request_id": "3b39072d-cc78-4dd9-98d0-0708f315da5f", "method": "GET", "URL": "/config/v1/agents?service.name=myMicroservice&service.environment=Development", "content_length": 0, "remote_address": "172.22.0.6", "user-agent": "elasticapm-dotnet/1.6.1 System.Net.Http/4.700.20.47203 .NET_Core/3.1.9", "response_code": 200}

2020-10-19T09:54:18.155Z INFO [request] middleware/log_middleware.go:97 not modified {"request_id": "121e9bc3-1b2f-4318-a129-a34b0db3bf9d", "method": "GET", "URL": "/config/v1/agents?service.name=myMicroservice&service.environment=Development", "content_length": 0, "remote_address": "172.22.0.6", "user-agent": "elasticapm-dotnet/1.6.1 System.Net.Http/4.700.20.47203 .NET_Core/3.1.9", "response_code": 304}

2020-10-19T09:54:27.558Z INFO [request] middleware/log_middleware.go:97 request accepted {"request_id": "b06c4c10-adf4-4cd2-92e0-50ddf117353d", "method": "POST", "URL": "/intake/v2/events", "content_length": 1157, "remote_address": "172.22.0.6", "user-agent": "elasticapm-dotnet/1.6.1 System.Net.Http/4.700.20.47203 .NET_Core/3.1.9", "response_code": 202}

2020-10-19T09:54:47.568Z INFO [request] middleware/log_middleware.go:97 request accepted {"request_id": "a5d42be3-8aab-485d-9a85-0e7072c8c382", "method": "POST", "URL": "/intake/v2/events", "content_length": 1160, "remote_address": "172.22.0.6", "user-agent": "elasticapm-dotnet/1.6.1 System.Net.Http/4.700.20.47203 .NET_Core/3.1.9", "response_code": 202}

2020-10-19T09:54:48.412Z INFO [request] middleware/log_middleware.go:97 not modified {"request_id": "ab3ee5eb-363e-4ce3-9a28-01c5aaed8ce1", "method": "GET", "URL": "/config/v1/agents?service.name=myMicroservice&service.environment=Development", "content_length": 0, "remote_address": "172.22.0.6", "user-agent": "elasticapm-dotnet/1.6.1 System.Net.Http/4.700.20.47203 .NET_Core/3.1.9", "response_code": 304}

2020-10-19T09:55:17.584Z INFO [request] middleware/log_middleware.go:97 request accepted {"request_id": "3a11b1aa-16bf-4c9f-93c6-3958d306e038", "method": "POST", "URL": "/intake/v2/events", "content_length": 1156, "remote_address": "172.22.0.6", "user-agent": "elasticapm-dotnet/1.6.1 System.Net.Http/4.700.20.47203 .NET_Core/3.1.9", "response_code": 202}

2020-10-19T09:55:18.476Z INFO [request] middleware/log_middleware.go:97 not modified {"request_id": "844307fe-ee65-4268-bcbd-11baec11d781", "method": "GET", "URL": "/config/v1/agents?service.name=myMicroservice&service.environment=Development", "content_length": 0, "remote_address": "172.22.0.6", "user-agent": "elasticapm-dotnet/1.6.1 System.Net.Http/4.700.20.47203 .NET_Core/3.1.9", "response_code": 304}

2020-10-19T09:55:48.633Z INFO [request] middleware/log_middleware.go:97 not modified {"request_id": "250b6b62-f234-4823-ac56-08f587e6ed2c", "method": "GET", "URL": "/config/v1/agents?service.name=myMicroservice&service.environment=Development", "content_length": 0, "remote_address": "172.22.0.6", "user-agent": "elasticapm-dotnet/1.6.1 System.Net.Http/4.700.20.47203 .NET_Core/3.1.9", "response_code": 304}

2020-10-19T09:55:48.944Z INFO [request] middleware/log_middleware.go:97 request accepted {"request_id": "96f48996-fb07-49a3-8b6f-b61a51ca0b48", "method": "POST", "URL": "/intake/v2/events", "content_length": 1153, "remote_address": "172.22.0.6", "user-agent": "elasticapm-dotnet/1.6.1 System.Net.Http/4.700.20.47203 .NET_Core/3.1.9", "response_code": 202}

2020-10-19T09:56:18.875Z INFO [request] middleware/log_middleware.go:97 not modified {"request_id": "4482eb21-109a-4cdb-9f47-f3d7711c4a80", "method": "GET", "URL": "/config/v1/agents?service.name=myMicroservice&service.environment=Development", "content_length": 0, "remote_address": "172.22.0.6", "user-agent": "elasticapm-dotnet/1.6.1 System.Net.Http/4.700.20.47203 .NET_Core/3.1.9", "response_code": 304}

One last thing (related ?) when I create an index pattern on the today logs (logstash-2020.10.19)
I see my logs, but not the the fields ElasticApmTransactionId and ElasticApmTraceId (cf https://www.elastic.co/guide/en/apm/agent/dotnet/current/serilog.html)

Is my logger the problem ?

I don't think the log correlation or the logger is the issue here, nested log level config should be fine - I think from some reason the APM Agent does not capture the incoming HTTP calls.

One idea to verify this would bot to turn off the log correlation and see if it makes a difference for the APM traces - I think it won't but of course I can be wrong.

So far I don't see anything wrong in the logs.

Have you tried setting only Elastic to Trace level? Like this:

 "Serilog": {
    "Using": [],
    "MinimumLevel": {
      "Default": "Information",
      "Override": {
        "Microsoft": "Warning",
        "System": "Information",
        "Elastic": "Trace"
      }
    },
...

@GregKalapos

Thank you spending time on my problem.

When adding "Elastic": "Trace" in this section , I get the following exception on CreateLogger() call

An unhandled exception of type 'System.InvalidOperationException' occurred in Serilog.Settings.Configuration.dll: 'No LoggingLevelSwitch has been declared with name "Trace". You might be missing a section "LevelSwitches":{"Trace":"InitialLevel"}'
Stack trace:
 >   at Serilog.Settings.Configuration.ResolutionContext.LookUpSwitchByName(String switchName)

I'm pretty sure it's my APM that is misconfigured, could you provide a full working sample that I could test on my stack ?
Or do you have other ideas to solve this problem ?

Thank you

@GregKalapos

I didn't mention that those logs and all http calls are made in a class implementing IHostedService interface and launched from ConfigureServices method with services.AddHostedService<myBackgroundService>() could it be linked ?

@GregKalapos

replacing 'Trace' with 'Verbose' for 'Elastic', here is the full log (sorry for the size), do you see any relevant information ?

[https://gofile.io/d/WWI0Nl](Apm no correlation logs with serilog)

On the serilog error: sorry, that was my mistake, serilog doesn't have Trace level, they call it Verbose, so I'd go with that.

I didn't mention that those logs and all http calls are made in a class implementing IHostedService interface and launched from ConfigureServices method with services.AddHostedService<myBackgroundService>() could it be linked ?

Ok, this explains a lot - but I'm also a but confused at the same time :slight_smile:

For background services you'll need to start the transaction manually in your code - but if you also have a "traditional" ASP.NET Core part which respond to incoming HTTP requests then those are automatically captured. Do you have an ASP.NET Core WebApi? Or some MVC? Or Razor pages? Anything like that?

ps: I'm looking at your logs - one sec and I'll respond what I see there.

Ok, the logs explain what happens. So you have outgoing HTTP calls, not incoming calls.

Outgoing HTTP calls are captured as a span only when there is an active transaction - the transaction is started automatically e.g. for incoming HTTP calls, but not in a Background Server.

In order to start the transaction manually you'll need to use the Public Agent API.

Like this:

var transaction = Elastic.Apm.Agent
        .Tracer.StartTransaction("MyTransaction", ApiConstants.TypeRequest);
try
{
    //application code that is captured as a transaction
}
catch (Exception e)
{
    transaction.CaptureException(e);
    throw;
}
finally
{
    transaction.End();
}

You can also dependency inject the Elastic.Apm.Agent.Tracer to avoid using the static API. Alternatively there is also another API:

Elastic.Apm.Agent.Tracer
        .CaptureTransaction("TestTransaction", ApiConstants.TypeRequest, (t) =>
{
   //application code that is captured as a transaction
});

@GregKalapos

My bad, I read it somewhere (about background service) I should have started with it...

Ok I'll handle the transaction manually, and no, I didn't have any MVC nor API, except a healthcheck and readyness endpoints, they work like a charm (not tested before)

Does that also mean that, regardless of what I'm doing in the background service (just logging or outgoing request), no correlation log will be reported to APM unless I manually create the transaction ?

Many many thanks for your precious help

That's correct, because you correlate your logs to traces, and you only have a trace if you have an active transaction - otherwise there is nothing to correlate to.

That makes sense, thank you very much

1 Like

This topic was automatically closed 20 days after the last reply. New replies are no longer allowed.