search

kyma-project / kyma

Kyma is an opinionated set of Kubernetes-based modular building blocks, including all necessary capabilities to develop and run enterprise-grade cloud-native applications.
https://kyma-project.io
Apache License 2.0
1.51k stars 406 forks source link

Cannot send event because of bad password for user eventbus in nats streaming #10548

Closed pbochynski closed 3 years ago

pbochynski commented 3 years ago

Description

Sending event through event-service fails with 500 error.

Expected result

The event is delivered.

Actual result

Steps to reproduce

Install Kyma and execute fast-integration tests with commerce-mock:

git clone git@github.com:kyma-incubator/local-kyma.git
cd local-kyma
./download-kyma-charts.sh 
./kyma-k3d.sh
cd tests/fast-integration
npm install
DEBUG=true npx mocha -b test/2-commerce-mock.js

It is not reproducible in each run. About 10% of executions fail this way.

Troubleshooting

kubectl logs -n kyma-integration commerce-c8cc4df7-9pkmb source

{"level":"error","ts":"2021-02-08T20:26:25.076Z","logger":"http-source","caller":"http/adapter.go:208","msg":"failed to send cloudevent to sink","error":"error sending cloudevent: 500 Internal Server Error","sink":"http://commerce-kn-channel.kyma-integration.svc.cluster.local","stacktrace":"github.com/kyma-project/kyma/components/event-sources/adapter/http.(*httpAdapter).serveHTTP\n\t/go/src/github.com/kyma-project/kyma/components/event-sources/adapter/http/adapter.go:208\nreflect.Value.call\n\t/usr/local/go/src/reflect/value.go:460\nreflect.Value.Call\n\t/usr/local/go/src/reflect/value.go:321\ngithub.com/kyma-project/kyma/components/event-sources/vendor/github.com/cloudevents/sdk-go/pkg/cloudevents/client.(*receiverFn).invoke\n\t/go/src/github.com/kyma-project/kyma/components/event-sources/vendor/github.com/cloudevents/sdk-go/pkg/cloudevents/client/receiver.go:93\ngithub.com/kyma-project/kyma/components/event-sources/vendor/github.com/cloudevents/sdk-go/pkg/cloudevents/client.(*ceClient).obsReceive\n\t/go/src/github.com/kyma-project/kyma/components/event-sources/vendor/github.com/cloudevents/sdk-go/pkg/cloudevents/client/client.go:133\ngithub.com/kyma-project/kyma/components/event-sources/vendor/github.com/cloudevents/sdk-go/pkg/cloudevents/client.(*ceClient).Receive\n\t/go/src/github.com/kyma-project/kyma/components/event-sources/vendor/github.com/cloudevents/sdk-go/pkg/cloudevents/client/client.go:121\ngithub.com/kyma-project/kyma/components/event-sources/vendor/github.com/cloudevents/sdk-go/pkg/cloudevents/transport/http.(*Transport).obsInvokeReceiver\n\t/go/src/github.com/kyma-project/kyma/components/event-sources/vendor/github.com/cloudevents/sdk-go/pkg/cloudevents/transport/http/transport.go:506\ngithub.com/kyma-project/kyma/components/event-sources/vendor/github.com/cloudevents/sdk-go/pkg/cloudevents/transport/http.(*Transport).invokeReceiver\n\t/go/src/github.com/kyma-project/kyma/components/event-sources/vendor/github.com/cloudevents/sdk-go/pkg/cloudevents/transport/http/transport.go:490\ngithub.com/kyma-project/kyma/components/event-sources/vendor/github.com/cloudevents/sdk-go/pkg/cloudevents/transport/http.(*Transport).ServeHTTP\n\t/go/src/github.com/kyma-project/kyma/components/event-sources/vendor/github.com/cloudevents/sdk-go/pkg/cloudevents/transport/http/transport.go:598\nnet/http.(*ServeMux).ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2416\ngithub.com/kyma-project/kyma/components/event-sources/vendor/go.opencensus.io/plugin/ochttp.(*Handler).ServeHTTP\n\t/go/src/github.com/kyma-project/kyma/components/event-sources/vendor/go.opencensus.io/plugin/ochttp/server.go:92\ngithub.com/kyma-project/kyma/components/event-sources/adapter/http.readinessMiddleware.ServeHTTP\n\t/go/src/github.com/kyma-project/kyma/components/event-sources/adapter/http/adapter.go:159\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2831\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1919"}

kubectl logs -n knative-eventing natss-ch-dispatcher-66dd8687fd-j9f58 dispatcher:

{"level":"error","ts":"2021-02-08T20:26:56.267Z","logger":"controller.natss-ch-dispatcher","caller":"dispatcher/natsschannel.go:182","msg":"\nNo Connection to NATSS","controller/impl":"pkg","knative.dev/controller":"natss-ch-dispatcher","knative.dev/traceid":"a3cb95f9-0e82-400d-87ac-3c44e3357f94","knative.dev/key":"test/default-kne-trigger","stacktrace":"knative.dev/eventing-contrib/natss/pkg/reconciler/dispatcher.(*Reconciler).reconcile\n\t/home/prow/go/src/knative.dev/eventing-contrib/natss/pkg/reconciler/dispatcher/natsschannel.go:182\nknative.dev/eventing-contrib/natss/pkg/reconciler/dispatcher.(*Reconciler).Reconcile\n\t/home/prow/go/src/knative.dev/eventing-contrib/natss/pkg/reconciler/dispatcher/natsschannel.go:135\nknative.dev/eventing-contrib/vendor/knative.dev/pkg/controller.(*Impl).processNextWorkItem\n\t/home/prow/go/src/knative.dev/eventing-contrib/vendor/knative.dev/pkg/controller/controller.go:361\nknative.dev/eventing-contrib/vendor/knative.dev/pkg/controller.(*Impl).Run.func2\n\t/home/prow/go/src/knative.dev/eventing-contrib/vendor/knative.dev/pkg/controller/controller.go:310"}
{"level":"error","ts":"2021-02-08T20:26:56.267Z","logger":"controller.natss-ch-dispatcher","caller":"dispatcher/natsschannel.go:137","msg":"Error reconciling NatssChannel","controller/impl":"pkg","knative.dev/controller":"natss-ch-dispatcher","knative.dev/traceid":"a3cb95f9-0e82-400d-87ac-3c44e3357f94","knative.dev/key":"test/default-kne-trigger","error":"\nNo Connection to NATSS","stacktrace":"knative.dev/eventing-contrib/natss/pkg/reconciler/dispatcher.(*Reconciler).Reconcile\n\t/home/prow/go/src/knative.dev/eventing-contrib/natss/pkg/reconciler/dispatcher/natsschannel.go:137\nknative.dev/eventing-contrib/vendor/knative.dev/pkg/controller.(*Impl).processNextWorkItem\n\t/home/prow/go/src/knative.dev/eventing-contrib/vendor/knative.dev/pkg/controller/controller.go:361\nknative.dev/eventing-contrib/vendor/knative.dev/pkg/controller.(*Impl).Run.func2\n\t/home/prow/go/src/knative.dev/eventing-contrib/vendor/knative.dev/pkg/controller/controller.go:310"}
{"level":"error","ts":"2021-02-08T20:26:56.267Z","logger":"controller.natss-ch-dispatcher","caller":"controller/controller.go:376","msg":"Reconcile error","controller/impl":"pkg","knative.dev/controller":"natss-ch-dispatcher","error":"\nNo Connection to NATSS","stacktrace":"knative.dev/eventing-contrib/vendor/knative.dev/pkg/controller.(*Impl).handleErr\n\t/home/prow/go/src/knative.dev/eventing-contrib/vendor/knative.dev/pkg/controller/controller.go:376\nknative.dev/eventing-contrib/vendor/knative.dev/pkg/controller.(*Impl).processNextWorkItem\n\t/home/prow/go/src/knative.dev/eventing-contrib/vendor/knative.dev/pkg/controller/controller.go:362\nknative.dev/eventing-contrib/vendor/knative.dev/pkg/controller.(*Impl).Run.func2\n\t/home/prow/go/src/knative.dev/eventing-contrib/vendor/knative.dev/pkg/controller/controller.go:310"}
{"level":"info","ts":"2021-02-08T20:26:56.268Z","logger":"controller.natss-ch-dispatcher","caller":"controller/controller.go:363","msg":"Reconcile failed. Time taken: 881µs.","controller/impl":"pkg","knative.dev/controller":"natss-ch-dispatcher","knative.dev/traceid":"a3cb95f9-0e82-400d-87ac-3c44e3357f94","knative.dev/key":"test/default-kne-trigger"}
{"level":"info","ts":"2021-02-08T20:26:57.025Z","logger":"controller","caller":"stanutil/stanutil.go:29","msg":"Connect(): clusterId: kyma-nats-streaming; clientId: natss-ch-dispatcher; natssUrl: nats://eventbus:jSrqzDEmLfMG@nats-streaming.natss:4222"}
{"level":"error","ts":"2021-02-08T20:26:57.029Z","logger":"controller","caller":"stanutil/stanutil.go:32","msg":"Connect(): create new connection failed: nats: Authorization Violation","stacktrace":"knative.dev/eventing-contrib/natss/pkg/stanutil.Connect\n\t/home/prow/go/src/knative.dev/eventing-contrib/natss/pkg/stanutil/stanutil.go:32\nknative.dev/eventing-contrib/natss/pkg/dispatcher.(*SubscriptionsSupervisor).connectWithRetry\n\t/home/prow/go/src/knative.dev/eventing-contrib/natss/pkg/dispatcher/dispatcher.go:156"}
{"level":"error","ts":"2021-02-08T20:26:57.029Z","logger":"controller","caller":"dispatcher/dispatcher.go:165","msg":"Connect() failed with error: nats: Authorization Violation, retrying in 1s","stacktrace":"knative.dev/eventing-contrib/natss/pkg/dispatcher.(*SubscriptionsSupervisor).connectWithRetry\n\t/home/prow/go/src/knative.dev/eventing-contrib/natss/pkg/dispatcher/dispatcher.go:165"}
{"level":"info","ts":"2021-02-08T20:26:58.025Z","logger":"controller","caller":"stanutil/stanutil.go:29","msg":"Connect(): clusterId: kyma-nats-streaming; clientId: natss-ch-dispatcher; natssUrl: nats://eventbus:jSrqzDEmLfMG@nats-streaming.natss:4222"}

kubectl logs -n natss nats-streaming-0 nats-streaming

[1] 2021/02/08 20:26:41.028940 [ERR] 10.42.0.26:54172 - cid:2493 - Authorization Error - User "eventbus"
[1] 2021/02/08 20:26:41.029111 [DBG] 10.42.0.26:54172 - cid:2493 - Client connection closed
[1] 2021/02/08 20:26:42.028180 [DBG] 10.42.0.26:54230 - cid:2494 - Client connection created
[1] 2021/02/08 20:26:42.028749 [ERR] 10.42.0.26:54230 - cid:2494 - Authorization Error - User "eventbus"
[1] 2021/02/08 20:26:42.028871 [DBG] 10.42.0.26:54230 - cid:2494 - Client connection closed
[1] 2021/02/08 20:26:43.027648 [DBG] 10.42.0.26:54272 - cid:2495 - Client connection created
[1] 2021/02/08 20:26:43.028426 [ERR] 10.42.0.26:54272 - cid:2495 - Authorization Error - User "eventbus"
[1] 2021/02/08 20:26:43.028557 [DBG] 10.42.0.26:54272 - cid:2495 - Client connection closed
[1] 2021/02/08 20:26:44.027272 [DBG] 10.42.0.26:54336 - cid:2496 - Client connection created
[1] 2021/02/08 20:26:44.028077 [ERR] 10.42.0.26:54336 - cid:2496 - Authorization Error - User "eventbus"
[1] 2021/02/08 20:26:44.028276 [DBG] 10.42.0.26:54336 - cid:2496 - Client connection closed

The password from knative-eventing natss-ch-dispatcher is jSrqzDEmLfMG(nats://eventbus:jSrqzDEmLfMG@nats-streaming.natss:4222). But secret looks different:

Secret for the user
apiVersion: v1
data:
  password: dHFzdkNqcGpEeHBD
  username: ZXZlbnRidXM=
kind: Secret
metadata:
  annotations:
    meta.helm.sh/release-name: nats-streaming
    meta.helm.sh/release-namespace: natss
  labels:
    app.kubernetes.io/managed-by: Helm
  name: nats-user-eventbus
  namespace: knative-eventing
type: Opaque

The decoded password is: tqsvCjpjDxpC

Restarting natss-ch-dispatcher solves the issue.

It seems that secret nats-user-eventbus was regenerated after it was mounted to natss-ch-dispatcher. It happens when natss-streaming is not installed in the first shot (retry happens).

Links https://helm.sh/docs/howto/charts_tips_and_tricks/#be-careful-with-generating-random-values

pbochynski commented 3 years ago

The error happens frequently because natss-streaming installation fails frequently. Examples: https://github.com/kyma-incubator/local-kyma/runs/1853847670?check_suite_focus=true#step:4:73 https://github.com/kyma-incubator/local-kyma/runs/1850719897?check_suite_focus=true#step:4:76

k15r commented 3 years ago

Nats streaming will be removed from kyma in 1.21