Panic when using OIDC auth extensions on gRPC receivers starting at version v0.30.0 #3734

secat · 2021-07-28T14:43:34Z

Describe the bug

Starting at version v0.30.0, when configuring an OIDC auth extension on receiver, it generates a panic with the following error message: The unary server interceptor was already set and may not be reset.

Example:

$ ./bin/otelcol_linux_amd64 --config collector.yaml
2021-07-28T11:04:11.047-0400    info    service/collector.go:296        Starting otelcol...     {"Version": "v0.30.1-64-gde2df3f8", "NumCPU": 8}
2021-07-28T11:04:11.047-0400    info    service/collector.go:235        Loading configuration...
2021-07-28T11:04:11.048-0400    info    service/collector.go:251        Applying configuration...
2021-07-28T11:04:11.048-0400    info    builder/exporters_builder.go:264        Exporter was built.     {"kind": "exporter", "name": "otlp/0/traces/0"}
2021-07-28T11:04:11.049-0400    info    memorylimiter/memorylimiter.go:135      Using percentage memory limiter {"kind": "processor", "name": "memory_limiter/0/traces/0", "total_memory_mib": 28083, "limit_percentage": 80, "spike_limit_percentage": 20}
2021-07-28T11:04:11.049-0400    info    memorylimiter/memorylimiter.go:105      Memory limiter configured       {"kind": "processor", "name": "memory_limiter/0/traces/0", "limit_mib": 22466, "spike_limit_mib": 5616, "check_interval": 1}
2021-07-28T11:04:11.049-0400    info    builder/pipelines_builder.go:214        Pipeline was built.     {"pipeline_name": "traces/0", "pipeline_datatype": "traces"}
2021-07-28T11:04:11.049-0400    info    builder/receivers_builder.go:227        Receiver was built.     {"kind": "receiver", "name": "otlp/0/traces/0", "datatype": "traces"}
2021-07-28T11:04:11.049-0400    info    service/service.go:143  Starting extensions...
2021-07-28T11:04:11.049-0400    info    builder/extensions_builder.go:54        Extension is starting...        {"kind": "extension", "name": "oidc"}
2021-07-28T11:04:11.286-0400    info    builder/extensions_builder.go:60        Extension started.      {"kind": "extension", "name": "oidc"}
2021-07-28T11:04:11.286-0400    info    service/service.go:188  Starting exporters...
2021-07-28T11:04:11.286-0400    info    builder/exporters_builder.go:93 Exporter is starting... {"kind": "exporter", "name": "otlp/0/traces/0"}
2021-07-28T11:04:11.286-0400    info    builder/exporters_builder.go:98 Exporter started.       {"kind": "exporter", "name": "otlp/0/traces/0"}
2021-07-28T11:04:11.286-0400    info    service/service.go:193  Starting processors...
2021-07-28T11:04:11.286-0400    info    builder/pipelines_builder.go:52 Pipeline is starting... {"pipeline_name": "traces/0", "pipeline_datatype": "traces"}
2021-07-28T11:04:11.286-0400    info    builder/pipelines_builder.go:63 Pipeline is started.    {"pipeline_name": "traces/0", "pipeline_datatype": "traces"}
2021-07-28T11:04:11.286-0400    info    service/service.go:198  Starting receivers...
2021-07-28T11:04:11.286-0400    info    builder/receivers_builder.go:71 Receiver is starting... {"kind": "receiver", "name": "otlp/0/traces/0"}
panic: The unary server interceptor was already set and may not be reset.

goroutine 1 [running]:
google.golang.org/grpc.UnaryInterceptor.func1(0xc0008c2000)
        google.golang.org/grpc@v1.39.0/server.go:382 +0x6b
google.golang.org/grpc.(*funcServerOption).apply(0xc00000e1a8, 0xc0008c2000)
        google.golang.org/grpc@v1.39.0/server.go:201 +0x33
google.golang.org/grpc.NewServer(0xc0000a99e0, 0x5, 0x6, 0x5)
        google.golang.org/grpc@v1.39.0/server.go:564 +0xeb
go.opentelemetry.io/collector/receiver/otlpreceiver.(*otlpReceiver).startProtocolServers(0xc0000b3090, 0x37eea60, 0xc000b66078, 0x32b1c4d, 0x17)
        go.opentelemetry.io/collector/receiver/otlpreceiver/otlp.go:118 +0x1c7
go.opentelemetry.io/collector/receiver/otlpreceiver.(*otlpReceiver).Start(0xc0000b3090, 0x37ed448, 0xc000052088, 0x37eea60, 0xc000b66078, 0x0, 0x0)
        go.opentelemetry.io/collector/receiver/otlpreceiver/otlp.go:166 +0x3f
go.opentelemetry.io/collector/internal/sharedcomponent.(*SharedComponent).Start.func1()
        go.opentelemetry.io/collector/internal/sharedcomponent/sharedcomponent.go:74 +0x63
sync.(*Once).doSlow(0xc0004c6a90, 0xc000c1f6e8)
        sync/once.go:68 +0xec
sync.(*Once).Do(...)
        sync/once.go:59
go.opentelemetry.io/collector/internal/sharedcomponent.(*SharedComponent).Start(0xc0004c6a80, 0x37ed448, 0xc000052088, 0x37eea60, 0xc000b66078, 0x0, 0xf1d29d)
        go.opentelemetry.io/collector/internal/sharedcomponent/sharedcomponent.go:73 +0xd3
go.opentelemetry.io/collector/service/internal/builder.(*builtReceiver).Start(...)
        go.opentelemetry.io/collector/service/internal/builder/receivers_builder.go:44
go.opentelemetry.io/collector/service/internal/builder.Receivers.StartAll(0xc0004c69c0, 0x37ed448, 0xc000052088, 0x37eea28, 0xc0006aac80, 0x0, 0x0)
        go.opentelemetry.io/collector/service/internal/builder/receivers_builder.go:73 +0x1a2
go.opentelemetry.io/collector/service.(*service).startPipelines(0xc0006aac80, 0x37ed448, 0xc000052088, 0x0, 0x0)
        go.opentelemetry.io/collector/service/service.go:199 +0x278
go.opentelemetry.io/collector/service.(*service).Start(0xc0006aac80, 0x37ed448, 0xc000052088, 0x0, 0x0)
        go.opentelemetry.io/collector/service/service.go:78 +0xe8
go.opentelemetry.io/collector/service.(*Collector).setupConfigurationComponents(0xc000354790, 0x37ed448, 0xc000052088, 0xc0006a6180, 0x2)
        go.opentelemetry.io/collector/service/collector.go:266 +0x3bf
go.opentelemetry.io/collector/service.(*Collector).execute(0xc000354790, 0x37ed448, 0xc000052088, 0xc0006a8700, 0x0)
        go.opentelemetry.io/collector/service/collector.go:310 +0x325
go.opentelemetry.io/collector/service.New.func1(0xc0006ae280, 0xc000696f60, 0x0, 0x2, 0x0, 0x0)
        go.opentelemetry.io/collector/service/collector.go:130 +0x22a
github.com/spf13/cobra.(*Command).execute(0xc0006ae280, 0xc00004c190, 0x2, 0x2, 0xc0006ae280, 0xc00004c190)
        github.com/spf13/cobra@v1.2.1/command.go:856 +0x472
github.com/spf13/cobra.(*Command).ExecuteC(0xc0006ae280, 0xc0006a2b40, 0xc0006a29c0, 0xc0006a24e0)
        github.com/spf13/cobra@v1.2.1/command.go:974 +0x375
github.com/spf13/cobra.(*Command).Execute(...)
        github.com/spf13/cobra@v1.2.1/command.go:902
go.opentelemetry.io/collector/service.(*Collector).Run(...)
        go.opentelemetry.io/collector/service/collector.go:167
main.runInteractive(0xc0006a26f0, 0xc0006a2b40, 0xc0006a29c0, 0xc0006a24e0, 0x328f2b4, 0x7, 0x32b1af4, 0x17, 0x37293e0, 0x14, ...)
        go.opentelemetry.io/collector/cmd/otelcol/main.go:51 +0x11e
main.run(...)
        go.opentelemetry.io/collector/cmd/otelcol/main_others.go:22
main.main()
        go.opentelemetry.io/collector/cmd/otelcol/main.go:40 +0x218

Steps to reproduce

Enable a gRPC OTLP receiver using the OIDC auth extension and start the otel-collector application binary.

What did you expect to see?

I expect the application to not panic and crash.

What did you see instead?

The application panics and crashes.

What version did you use?

Versions v0.30.0 and v0.30.1.

What config did you use?

Here is a config example:

receivers:
  otlp/0/traces/0:
    protocols:
      grpc:
        endpoint: 0.0.0.0:55680
        auth:
          authenticator: oidc
      http:
        endpoint: 0.0.0.0:55681
processors:
  batch/1/traces/0: null
  memory_limiter/0/traces/0:
    check_interval: 1s
    limit_mib: 0
    spike_limit_mib: 0
    limit_percentage: 80
    spike_limit_percentage: 20
exporters:
  otlp/0/traces/0:
    endpoint: tempo:4317
    insecure: true
extensions:
  oidc:
    issuer_url: https://cognito-idp.us-east-1.amazonaws.com/us-east-1_xxxxxxxx
    audience: account
    username_claim: email
service:
  extensions:
  - oidc
  pipelines:
    traces/0:
      receivers:
      - otlp/0/traces/0
      processors:
      - memory_limiter/0/traces/0
      - batch/1/traces/0
      exporters:
      - otlp/0/traces/0

NOTE: This config works with version v0.29.0

Environment

OS: Ubuntu 18.04
Compiler: go 16.4

The text was updated successfully, but these errors were encountered:

secat · 2021-07-28T15:07:22Z

@jpkrohling did you encountered this with latest opentelemetry-collector version?

jpkrohling · 2021-07-29T07:04:49Z

I don't remember seeing this, but will try to reproduce and fix ASAP.

TheKevJames · 2021-07-30T01:29:29Z

I also just ran into this -- can confirm the bug is still present under v0.31.0 in the same way @secat described.

jpkrohling · 2021-07-30T08:09:27Z

I'm on it.

jpkrohling · 2021-07-30T08:37:59Z

git bisect tells me that this is caused by #3567

fb95c88e72fa98f31b694703ec2787fe09381154 is the first bad commit
commit fb95c88e72fa98f31b694703ec2787fe09381154
Author: Bogdan Drutu <bogdandrutu@gmail.com>
Date:   Thu Jul 8 16:53:11 2021 -0700

    Change internal tracing to use otel trace (#3567)
    
    For the moment we rely on the global TracerProvider, in a future PR will change that.
    
    Signed-off-by: Bogdan Drutu <bogdandrutu@gmail.com>

 config/configgrpc/configgrpc.go                    |  12 +-
 config/configgrpc/configgrpc_test.go               |  10 +-
 exporter/exporterhelper/common_test.go             |  18 +-
 exporter/exporterhelper/logs_test.go               |  48 +--
 exporter/exporterhelper/metrics_test.go            |  48 +--
 exporter/exporterhelper/queued_retry.go            |  37 +-
 exporter/exporterhelper/traces_test.go             |  61 ++--
 go.mod                                             |   4 +
 go.sum                                             |  10 +
 obsreport/obsreport.go                             |  37 +-
 obsreport/obsreport_exporter.go                    |  54 +--
 obsreport/obsreport_receiver.go                    |  35 +-
 obsreport/obsreport_scraper.go                     |  23 +-
 obsreport/obsreport_test.go                        | 381 ++++++++++-----------
 processor/processorhelper/logs.go                  |  10 +-
 processor/processorhelper/metrics.go               |  10 +-
 processor/processorhelper/processor.go             |   9 +-
 processor/processorhelper/traces.go                |  10 +-
 .../internal/octrace/observability_test.go         |  84 +----
 .../internal/octrace/opencensus_test.go            |   6 +-
 receiver/scraperhelper/scrapercontroller_test.go   |  56 +--
 21 files changed, 437 insertions(+), 526 deletions(-)

Signed-off-by: Juraci Paixão Kröhling <juraci@kroehling.de> Fixes #3734 by using chained interceptors for the gRPC servers. The tests making use of ToServerOptions were also changed to call grpc.NewServer with the obtained options, ensuring that they are valid. The test TestGrpcServerAuthSettings now calling grpc.NewServer, executed against the configgrpc without the chained interceptors confirms the bug: ``` $ go test ./config/configgrpc/ --- FAIL: TestGrpcServerAuthSettings (0.00s) panic: The unary server interceptor was already set and may not be reset. [recovered] panic: The unary server interceptor was already set and may not be reset. goroutine 23 [running]: testing.tRunner.func1.2(0xa6c2a0, 0xc0b8a0) /home/jpkroehling/bin/go/src/testing/testing.go:1144 +0x332 testing.tRunner.func1(0xc000103b00) /home/jpkroehling/bin/go/src/testing/testing.go:1147 +0x4b6 panic(0xa6c2a0, 0xc0b8a0) /home/jpkroehling/bin/go/src/runtime/panic.go:965 +0x1b9 google.golang.org/grpc.UnaryInterceptor.func1(0xc000374500) /home/jpkroehling/go/pkg/mod/google.golang.org/grpc@v1.39.0/server.go:382 +0x6b google.golang.org/grpc.(*funcServerOption).apply(0xc0001243f0, 0xc000374500) /home/jpkroehling/go/pkg/mod/google.golang.org/grpc@v1.39.0/server.go:201 +0x33 google.golang.org/grpc.NewServer(0xc000129900, 0x4, 0x4, 0x4) /home/jpkroehling/go/pkg/mod/google.golang.org/grpc@v1.39.0/server.go:564 +0xeb go.opentelemetry.io/collector/config/configgrpc.TestGrpcServerAuthSettings(0xc000103b00) /home/jpkroehling/Projects/src/github.com/open-telemetry/opentelemetry-collector/config/configgrpc/configgrpc_test.go:140 +0x2aa testing.tRunner(0xc000103b00, 0xb85528) /home/jpkroehling/bin/go/src/testing/testing.go:1194 +0xef created by testing.(*T).Run /home/jpkroehling/bin/go/src/testing/testing.go:1239 +0x2b3 FAIL go.opentelemetry.io/collector/config/configgrpc 0.006s FAIL ```

secat · 2021-07-30T15:27:43Z

thanks @jpkrohling for the quick fix!

secat added the bug Something isn't working label Jul 28, 2021

bogdandrutu assigned jpkrohling Jul 28, 2021

jpkrohling mentioned this issue Jul 30, 2021

Use chained interceptors in the gRPC server #3744

Merged

tigrannajaryan closed this as completed in #3744 Jul 30, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Panic when using OIDC auth extensions on gRPC receivers starting at version v0.30.0 #3734

Panic when using OIDC auth extensions on gRPC receivers starting at version v0.30.0 #3734

secat commented Jul 28, 2021 •

edited

Loading

secat commented Jul 28, 2021

jpkrohling commented Jul 29, 2021

TheKevJames commented Jul 30, 2021

jpkrohling commented Jul 30, 2021

jpkrohling commented Jul 30, 2021 •

edited

Loading

secat commented Jul 30, 2021

Panic when using OIDC auth extensions on gRPC receivers starting at version v0.30.0 #3734

Panic when using OIDC auth extensions on gRPC receivers starting at version v0.30.0 #3734

Comments

secat commented Jul 28, 2021 • edited Loading

secat commented Jul 28, 2021

jpkrohling commented Jul 29, 2021

TheKevJames commented Jul 30, 2021

jpkrohling commented Jul 30, 2021

jpkrohling commented Jul 30, 2021 • edited Loading

secat commented Jul 30, 2021

secat commented Jul 28, 2021 •

edited

Loading

jpkrohling commented Jul 30, 2021 •

edited

Loading