otlp.setLabel panic on non-compliant attribute array values

[leehow1988]

APM Server version (8.8.1 and 8.10.0 and 8.14.3):

apm-server exits for unknown reason, logs can see otpl related stack

Steps to reproduce:

We have a lot of services in our test environment, some of them use OpenTelemetry, some of them use Elastic APM Agent We found today that apm-server exits shortly after starting, as shown in the attached file

I started ELK using docker-compose,yaml, and the part about apm-server is as follows:

  apm-server:
    image: docker.elastic.co/apm/apm-server:8.14.3
    cap_add: ["CHOWN", "DAC_OVERRIDE", "SETGID", "SETUID"]
    cap_drop: ["ALL"]
    ports:
      - 8200:8200
    depends_on:
      - elasticsearch
      - kibana
    networks:
      - elk
    volumes:
      - ./apm-server/config/apm-server.yml:/usr/share/apm-server/apm-server.yml
      - /home/elk_data/apm-server/logs:/usr/share/apm-server/logs
      - /home/elk_data/apm-server/data:/usr/share/apm-server/data
    healthcheck:
      interval: 10s
      retries: 12
      test: curl --write-out 'HTTP %{http_code}' --fail --silent --output /dev/null http://localhost:8200/

apm-server.yaml content

apm-server:
  host: "0.0.0.0:8200"

  kibana:
    enabled: true
    host: "192.168.3.155:5601"
    username: "elastic"
    password: "***"

#-------------------------- Elasticsearch output --------------------------
output.elasticsearch:
  hosts: ["192.168.3.155:9200"]
  enabled: true
  username: "elastic"
  password: "***"

docker inspect elk-apm-server-1 |grep ExitCode -C 10

"State": {
    "Status": "exited",
    "Running": false,
    "Paused": false,
    "Restarting": false,
    "OOMKilled": false,
    "Dead": false,
    "Pid": 0,
    "ExitCode": 2,
    "Error": "",
    "StartedAt": "2024-07-16T08:08:36.738792834Z",
    "FinishedAt": "2024-07-16T08:11:38.74994692Z",
    "Health": {
        "Status": "unhealthy",
        "FailingStreak": 17,
        "Log": [
            {
                "Start": "2024-07-16T16:10:52.268632964+08:00",
                "End": "2024-07-16T16:10:52.7597741+08:00",
                "ExitCode": 127,
                "Output": "/bin/sh: 1: curl: not found\n"
            },
            {
                "Start": "2024-07-16T16:11:02.763336696+08:00",
                "End": "2024-07-16T16:11:02.860034212+08:00",
                "ExitCode": 127,
                "Output": "/bin/sh: 1: curl: not found\n"
            },
            {
                "Start": "2024-07-16T16:11:12.891897649+08:00",
                "End": "2024-07-16T16:11:12.998785585+08:00",
                "ExitCode": 127,
                "Output": "/bin/sh: 1: curl: not found\n"
            },
            {
                "Start": "2024-07-16T16:11:23.005486378+08:00",
                "End": "2024-07-16T16:11:23.096787177+08:00",
                "ExitCode": 127,
                "Output": "/bin/sh: 1: curl: not found\n"
            },
            {
                "Start": "2024-07-16T16:11:33.098991014+08:00",
                "End": "2024-07-16T16:11:33.258413466+08:00",
                "ExitCode": 127,
                "Output": "/bin/sh: 1: curl: not found\n"
            }
        ]
    }
}

Provide logs (if relevant): see attachment file

error.log

[carsonip]

The core of the issue is shown in your error log:

panic: interface conversion: interface {} is nil, not string
goroutine 3684 [running]:
github.com/elastic/apm-data/input/otlp.setLabel({0xc00502e960, 0x1b}, 0xc003ccef20, {0x1c9da00?, 0xc000ca7710?})
        github.com/elastic/apm-data@v1.1.0/input/otlp/metadata.go:508 +0x5f1
github.com/elastic/apm-data/input/otlp.TranslateTransaction.func1({0xc004fcc600, 0x1b}, {0xc0012a8e50?, 0xc0050564dc?})
        github.com/elastic/apm-data@v1.1.0/input/otlp/traces.go:290 +0x8be
go.opentelemetry.io/collector/pdata/pcommon.Map.Range({0xc0041ebaa0?, 0xc0050564dc?}, 0xc000b7a978)
        go.opentelemetry.io/collector/pdata@v1.5.0/pcommon/map.go:222 +0x97

I managed to reproduce the issue by crafting an invalid otlp payload. It is invalid because according to OTel spec, arrays MUST be homogeneous, and nulls SHOULD NOT be allowed in arrays.

Please double check your OTel collectors and understand why they are sending attributes that do not comply to OTel spec. At the same time, we will improve handling in apm-server to handle this kind of invalid payload.

[leehow1988]

thanks for reply. Hope that later versions will ignore this invalid payload and let the apm-server run normally.

[kruskall]

Released v1.11.0 (https://github.com/elastic/apm-data/releases/tag/v1.11.0)

@rubvs let's wait for dependabot to pick up the new version and update it in apm-server 🙂

[kruskall]

Dependabot PR Merged: #13950

[matglas]

When can the new release be expected for apm-server?

[rubvs]

When can the new release be expected for apm-server?

@matglas, the fix is scheduled to be shipped in 8.15.2

[kikmon]

H
I updated to 8.15.2 and I'm sill getting some "panic: interface conversion: interface {} is nil, not string" issues
Is it possible the issue isn't entirely fixed ?

[rubvs]

Hi @kikmon, can you give some more details please; setup, input, output expected, error logs, etc. Thanks

[kikmon]

Setup is quite basic.
Just running 8.15.2 windows version of ES and APM.
Input is a Jenkins server using the opentelemetry plugin
apm_server works fine with an empty test instance of Jenkins, but when fed with the real instance, apm_server panics after a few seconds.
in the latest log, there seem to be some tags with empty value. Maybe that's what's making apm panic (would be nice to know what stat exactly made it panic)

Here's the full callstack if it helps
panic: interface conversion: interface {} is nil, not string

goroutine 172 [running]:
github.com/elastic/apm-data/input/otlp.setLabel({0xc0003a1600, 0x1b}, 0xc000a98000, {0x20b95c0?, 0xc000586a98?})
github.com/elastic/apm-data@v1.9.1/input/otlp/metadata.go:532 +0x5f1
github.com/elastic/apm-data/input/otlp.TranslateTransaction.func1({0xc00011b1a0, 0x1b}, {0xc00044a570?, 0xc0019b6b08?})
github.com/elastic/apm-data@v1.9.1/input/otlp/traces.go:295 +0x90a
go.opentelemetry.io/collector/pdata/pcommon.Map.Range({0xc0003118e0?, 0xc0019b6b08?}, 0xc0006da968)
go.opentelemetry.io/collector/pdata@v1.12.0/pcommon/map.go:222 +0x97
github.com/elastic/apm-data/input/otlp.TranslateTransaction({0xc0003118e0?, 0xc0019b6b08?}, {0xc000311940?, 0xc0019b6b08?}, {0xc000344070?, 0xc0019b6b08?}, 0xc000a98000)
github.com/elastic/apm-data@v1.9.1/input/otlp/traces.go:269 +0x2b7
github.com/elastic/apm-data/input/otlp.(*Consumer).convertSpan(0xc0002abb60, {0xc000311880?, 0xc0019b6b08?}, {0xc000344070?, 0xc0019b6b08?}, 0xc0004d6840, 0x0, 0xc0005869c0)
github.com/elastic/apm-data@v1.9.1/input/otlp/traces.go:209 +0x8da
github.com/elastic/apm-data/input/otlp.(*Consumer).convertScopeSpans(0xc0002abb60, {0xc000344070?, 0xc0019b6b08?}, 0xc0004d6840, 0x0, 0xc0005869c0)
github.com/elastic/apm-data@v1.9.1/input/otlp/traces.go:151 +0x70
github.com/elastic/apm-data/input/otlp.(*Consumer).convertResourceSpans(0xc0002abb60, {0xc0004261e0?, 0xc0019b6b08?}, {0xc000a84e00?, 0x1?, 0x3cb9340?}, 0xc0005869c0)
github.com/elastic/apm-data@v1.9.1/input/otlp/traces.go:139 +0x1ac
github.com/elastic/apm-data/input/otlp.(*Consumer).ConsumeTracesWithResult(0xc0002abb60, {0x28dcfb8, 0xc00132c3f0}, {0xc00052e180?, 0xc0019b6b08?})
github.com/elastic/apm-data@v1.9.1/input/otlp/traces.go:115 +0x332
github.com/elastic/apm-server/internal/beater/otlp.(*tracesService).Export(0xc0004fe238, {0x28dcfb8, 0xc00132c3f0}, {0xc00052e180?, 0xc0019b6b08?})
github.com/elastic/apm-server/internal/beater/otlp/grpc.go:100 +0x9d
go.opentelemetry.io/collector/pdata/ptrace/ptraceotlp.rawTracesServer.Export({{0x28d3690?, 0xc0004fe238?}}, {0x28dcfb8, 0xc00132c3f0}, 0xc00052e180)
go.opentelemetry.io/collector/pdata@v1.12.0/ptrace/ptraceotlp/grpc.go:89 +0xea
go.opentelemetry.io/collector/pdata/internal/data/protogen/collector/trace/v1._TraceService_Export_Handler.func1({0x28dcfb8?, 0xc00132c3f0?}, {0x24309c0?, 0xc00052e180?})
go.opentelemetry.io/collector/pdata@v1.12.0/internal/data/protogen/collector/trace/v1/trace_service.pb.go:310 +0xcb
github.com/elastic/apm-server/internal/beater.(*Runner).Run.AnonymousRateLimit.func22({0x28dcfb8, 0xc00132c3f0}, {0x24309c0, 0xc00052e180}, 0x18d0165?, 0xc00052e300)
github.com/elastic/apm-server/internal/beater/interceptors/ratelimit.go:59 +0x174
google.golang.org/grpc.getChainUnaryHandler.func1({0x28dcfb8, 0xc00132c3f0}, {0x24309c0, 0xc00052e180})
google.golang.org/grpc@v1.65.0/server.go:1196 +0xb2
github.com/elastic/apm-server/internal/beater.(*Runner).Run.Auth.func21({0x28dcfb8, 0xc00132c330}, {0x24309c0, 0xc00052e180}, 0xc000f14560?, 0xc000a84dc0)
github.com/elastic/apm-server/internal/beater/interceptors/auth.go:76 +0x16a
google.golang.org/grpc.getChainUnaryHandler.func1({0x28dcfb8, 0xc00132c330}, {0x24309c0, 0xc00052e180})
google.golang.org/grpc@v1.65.0/server.go:1196 +0xb2
github.com/elastic/apm-server/internal/beater.(*Runner).Run.Timeout.func20({0x28dcfb8?, 0xc00132c330?}, {0x24309c0?, 0xc00052e180?}, 0xc000f14560?, 0xc00052e300?)
github.com/elastic/apm-server/internal/beater/interceptors/timeout.go:40 +0x2e
google.golang.org/grpc.getChainUnaryHandler.func1({0x28dcfb8, 0xc00132c330}, {0x24309c0, 0xc00052e180})
google.golang.org/grpc@v1.65.0/server.go:1196 +0xb2
github.com/elastic/apm-server/internal/beater/interceptors.Metrics.(*metricsInterceptor).Interceptor.func1({0x28dcfb8, 0xc00132c330}, {0x24309c0, 0xc00052e180}, 0xc000f14560, 0xc000a84d40)
github.com/elastic/apm-server/internal/beater/interceptors/metrics.go:92 +0x26c
google.golang.org/grpc.getChainUnaryHandler.func1({0x28dcfb8, 0xc00132c330}, {0x24309c0, 0xc00052e180})
google.golang.org/grpc@v1.65.0/server.go:1196 +0xb2
github.com/elastic/apm-server/internal/beater.(*Runner).Run.Logging.func19({0x28dcfb8, 0xc00132c330}, {0x24309c0, 0xc00052e180}, 0xc000f14560, 0xc000a84c80)
github.com/elastic/apm-server/internal/beater/interceptors/logging.go:54 +0x1ce
google.golang.org/grpc.getChainUnaryHandler.func1({0x28dcfb8, 0xc00132c330}, {0x24309c0, 0xc00052e180})
google.golang.org/grpc@v1.65.0/server.go:1196 +0xb2
github.com/elastic/apm-server/internal/beater.(*Runner).Run.ClientMetadata.func18({0x28dcfb8, 0xc00132c2d0}, {0x24309c0, 0xc00052e180}, 0xc000f14560?, 0xc000a84c40)
github.com/elastic/apm-server/internal/beater/interceptors/metadata.go:66 +0x276
google.golang.org/grpc.getChainUnaryHandler.func1({0x28dcfb8, 0xc00132c2d0}, {0x24309c0, 0xc00052e180})
google.golang.org/grpc@v1.65.0/server.go:1196 +0xb2
go.elastic.co/apm/module/apmgrpc/v2.NewUnaryServerInterceptor.func1({0x28dcfb8?, 0xc00132c2d0?}, {0x24309c0?, 0xc00052e180?}, 0xc000f14560?, 0xc00052e300?)
go.elastic.co/apm/module/apmgrpc/v2@v2.6.0/server.go:71 +0xf6
google.golang.org/grpc.NewServer.chainUnaryServerInterceptors.chainUnaryInterceptors.func1({0x28dcfb8, 0xc00132c2d0}, {0x24309c0, 0xc00052e180}, 0xc000f14560, 0x80?)
google.golang.org/grpc@v1.65.0/server.go:1187 +0x85
go.opentelemetry.io/collector/pdata/internal/data/protogen/collector/trace/v1._TraceService_Export_Handler({0x21dd100, 0xc0003af190}, {0x28dcfb8, 0xc00132c2d0}, 0xc000286680, 0xc0003a86c0)
go.opentelemetry.io/collector/pdata@v1.12.0/internal/data/protogen/collector/trace/v1/trace_service.pb.go:312 +0x143
google.golang.org/grpc.(*Server).processUnaryRPC(0xc000314200, {0x28dcfb8, 0xc00132c210}, {0x28e7ba0, 0xc000638600}, 0xc000352360, 0xc0002eaf90, 0x3c7dba0, 0x0)
google.golang.org/grpc@v1.65.0/server.go:1379 +0xdf8
google.golang.org/grpc.(*Server).handleStream(0xc000314200, {0x28e7ba0, 0xc000638600}, 0xc000352360)
google.golang.org/grpc@v1.65.0/server.go:1790 +0xe8b
google.golang.org/grpc.(*Server).serveStreams.func2.1()
google.golang.org/grpc@v1.65.0/server.go:1029 +0x8b
created by google.golang.org/grpc.(*Server).serveStreams.func2 in goroutine 157
google.golang.org/grpc@v1.65.0/server.go:1040 +0x125

[rubvs]

Hi @kikmon , sorry for the late response. The fix was not introduced in 8.15.2 and will be implemented in an upcoming release.

[kikmon]

Thanks, it explains a lot :)