APM Agents configuration cache refresh appears to be broken

[up2neck]

APM Server version (apm-server version): 8.14.3 (linux/amd64), standalone

Description of the problem including expected versus actual behavior:

APM Server makes invalid search/scroll requests to ".apm-agent-configuration" Elasticsearch index:

Invalid transaction JSON

{
  "@timestamp": [
    "2024-08-30T09:11:00.105Z"
  ],
  "agent.name": [
    "go"
  ],
  "agent.version": [
    "2.6.0"
  ],
  "cloud.availability_zone": [
    ""
  ],
  "cloud.instance.id": [
    ""
  ],
  "cloud.instance.name": [
    ""
  ],
  "cloud.project.id": [
    ""
  ],
  "cloud.provider": [
    ""
  ],
  "cloud.region": [
    ""
  ],
  "data_stream.dataset": [
    "apm"
  ],
  "data_stream.namespace": [
    "default"
  ],
  "data_stream.type": [
    "traces"
  ],
  "destination.address": [
    "elasticsearch-v1-es-http.apm-sandbox.svc"
  ],
  "destination.port": [
    9200
  ],
  "event.agent_id_status": [
    "missing"
  ],
  "event.ingested": [
    "2024-08-30T09:11:01.000Z"
  ],
  "event.outcome": [
    "failure"
  ],
  "event.success_count": [
    0
  ],
  "host.architecture": [
    "amd64"
  ],
  "host.hostname": [
    "apm-server-v1-apm-server-68576fc56-6pkms"
  ],
  "host.name": [
    "apm-server-v1-apm-server-68576fc56-6pkms"
  ],
  "host.os.platform": [
    "linux"
  ],
  "http.response.status_code": [
    400
  ],
  "labels.project": [
    "epm-paas"
  ],
  "observer.hostname": [
    "apm-server-v1-apm-server-68576fc56-6pkms"
  ],
  "observer.type": [
    "apm-server"
  ],
  "observer.version": [
    "8.14.3"
  ],
  "parent.id": [
    "5ae92913235dc969"
  ],
  "process.args": [
    "apm-server",
    "run",
    "-e",
    "-c",
    "config/config-secret/apm-server.yml"
  ],
  "process.pid": [
    1
  ],
  "process.title": [
    "apm-server"
  ],
  "process.title.text": [
    "apm-server"
  ],
  "processor.event": [
    "span"
  ],
  "service.environment": [
    "sandbox"
  ],
  "service.language.name": [
    "go"
  ],
  "service.language.version": [
    "go1.22.5"
  ],
  "service.name": [
    "apm-server"
  ],
  "service.node.name": [
    "apm-server-v1-apm-server-68576fc56-6pkms"
  ],
  "service.runtime.name": [
    "gc"
  ],
  "service.runtime.version": [
    "go1.22.5"
  ],
  "service.target.type": [
    "elasticsearch"
  ],
  "service.version": [
    "8.14.3"
  ],
  "span.db.type": [
    "elasticsearch"
  ],
  "span.db.user.name": [
    "apm-sandbox-apm-server-v1-apm-user"
  ],
  "span.destination.service.name": [
    "elasticsearch"
  ],
  "span.destination.service.resource": [
    "elasticsearch"
  ],
  "span.destination.service.type": [
    "db"
  ],
  "span.duration.us": [
    82067
  ],
  "span.id": [
    "6c3c47e4d07a1c9a"
  ],
  "span.name": [
    "Elasticsearch: POST _search/scroll"
  ],
  "span.representative_count": [
    1
  ],
  "span.stacktrace": [
    {
      "exclude_from_grouping": false,
      "library_frame": true,
      "filename": "span.go",
      "line": {
        "number": 442
      },
      "function": "(*Span).End",
      "module": "go.elastic.co/apm/v2"
    },
    {
      "exclude_from_grouping": false,
      "library_frame": true,
      "filename": "client.go",
      "line": {
        "number": 161
      },
      "function": "(*responseBody).endSpan",
      "module": "go.elastic.co/apm/module/apmelasticsearch/v2"
    },
    {
      "exclude_from_grouping": false,
      "library_frame": true,
      "filename": "client.go",
      "line": {
        "number": 153
      },
      "function": "(*responseBody).Read",
      "module": "go.elastic.co/apm/module/apmelasticsearch/v2"
    },
    {
      "exclude_from_grouping": false,
      "library_frame": true,
      "filename": "stream.go",
      "line": {
        "number": 165
      },
      "function": "(*Decoder).refill",
      "module": "encoding/json"
    },
    {
      "exclude_from_grouping": false,
      "library_frame": true,
      "filename": "stream.go",
      "line": {
        "number": 140
      },
      "function": "(*Decoder).readValue",
      "module": "encoding/json"
    },
    {
      "exclude_from_grouping": false,
      "library_frame": true,
      "filename": "stream.go",
      "line": {
        "number": 63
      },
      "function": "(*Decoder).Decode",
      "module": "encoding/json"
    },
    {
      "exclude_from_grouping": false,
      "filename": "elasticsearch.go",
      "line": {
        "number": 288
      },
      "function": "(*ElasticsearchFetcher).singlePageRefresh",
      "module": "github.com/elastic/apm-server/internal/agentcfg"
    },
    {
      "exclude_from_grouping": false,
      "filename": "elasticsearch.go",
      "line": {
        "number": 223
      },
      "function": "(*ElasticsearchFetcher).refreshCache",
      "module": "github.com/elastic/apm-server/internal/agentcfg"
    },
    {
      "exclude_from_grouping": false,
      "filename": "elasticsearch.go",
      "line": {
        "number": 137
      },
      "function": "(*ElasticsearchFetcher).Run.func1",
      "module": "github.com/elastic/apm-server/internal/agentcfg"
    },
    {
      "exclude_from_grouping": false,
      "filename": "elasticsearch.go",
      "line": {
        "number": 179
      },
      "function": "(*ElasticsearchFetcher).Run",
      "module": "github.com/elastic/apm-server/internal/agentcfg"
    },
    {
      "exclude_from_grouping": false,
      "filename": "beater.go",
      "line": {
        "number": 452
      },
      "function": "(*Runner).Run.func8",
      "module": "github.com/elastic/apm-server/internal/beater"
    },
    {
      "exclude_from_grouping": false,
      "filename": "errgroup.go",
      "line": {
        "number": 78
      },
      "function": "(*Group).Go.func1",
      "module": "golang.org/x/sync/errgroup"
    },
    {
      "exclude_from_grouping": false,
      "library_frame": true,
      "filename": "asm_amd64.s",
      "line": {
        "number": 1695
      },
      "function": "goexit",
      "module": "runtime"
    }
  ],
  "span.subtype": [
    "elasticsearch"
  ],
  "span.type": [
    "db"
  ],
  "timestamp.us": [
    1725009060105160
  ],
  "trace.id": [
    "9dc612c94d0058a25ab50e62d45e430c"
  ],
  "transaction.id": [
    "9dc612c94d0058a2"
  ],
  "url.original": [
    "https://elasticsearch-v1-es-http.apm-sandbox.svc:9200/_search/scroll?scroll=30000ms"
  ],
  "url.original.text": [
    "https://elasticsearch-v1-es-http.apm-sandbox.svc:9200/_search/scroll?scroll=30000ms"
  ],
  "_id": "8BaNopEBbRHRTkfJaBr-",
  "_index": ".ds-traces-apm-default-2024.08.24-000002",
  "_score": 15.300476
}

Steps to reproduce:

1. Install standalone APM Server
2. Enable instrumentation for APM Server
3. Check APM Server transactions to Elasticsearch

Provide logs (if relevant):

[carsonip]

@up2neck thanks for reporting the issue. It is unexpected that Elasticsearch scroll API returns HTTP 400. It will be helpful if you could attach apm-server logs, especially the parts with "log.logger":"agentcfg". Please remove any sensitive information from the logs.

[up2neck]

@carsonip
I've spotted this issue only with APM self-instrumentation. Logs only contain info messages, like this:

    "log.logger": "agentcfg",
    "ecs.version": "1.6.0",
    "@timestamp": "2024-08-29T12:23:45.347Z",
    "message": "Cache creation with expiration 30s.",
    "service.name": "apm-server",
    "log.level": "info",
    "log.origin": {
      "file.name": "agentcfg/cache.go",
      "function": "github.com/elastic/apm-server/internal/agentcfg.newCache",
      "file.line": 38
    }

[carsonip]

I see that you've created a bugfix PR #13958 and it makes complete sense. Due to this bug, the scroll search payload is {} as the field isn't even emitted because it is empty, and that causes ES to return 400. There is no need for apm-server logs for investigation.

edit: it is HTTP 400 because scroll_id is missing from both query param and body. The go-elasticsearch client sends scroll id in query param, not body.