Keda: Service Bus scaler SAS Policy permissions documentation and error logs

[programaka]

I was trying to scale my app using Service Bus scaler. I was following the docs https://keda.sh/scalers/azure-service-bus/ and one of the samples.

Even though I got some messages in the queue, KEDA was scaling my app to 0 and was throwing some errors from which it was not clear at all what's wrong exactly:

{"level":"info","ts":1588728540.7852893,"logger":"controller_scaledobject","msg":"Reconciling ScaledObject","Request.Namespace":"default","Request.Name":"batch-processor-scaler"}
{"level":"info","ts":1588728540.7853305,"logger":"controller_scaledobject","msg":"Adding Finalizer for the ScaledObject","Request.Namespace":"default","Request.Name":"batch-processor-scaler"}
{"level":"info","ts":1588728540.792744,"logger":"controller_scaledobject","msg":"Detected ScaleType = Deployment","Request.Namespace":"default","Request.Name":"batch-processor-scaler"}
{"level":"info","ts":1588728540.7928522,"logger":"controller_scaledobject","msg":"Creating a new HPA","Request.Namespace":"default","Request.Name":"batch-processor-scaler","HPA.Namespace":"default","HPA.Name":"keda-hpa-batch-processor"}
{"level":"info","ts":1588728540.8081746,"logger":"controller_scaledobject","msg":"Reconciling ScaledObject","Request.Namespace":"default","Request.Name":"batch-processor-scaler"}
{"level":"info","ts":1588728540.808521,"logger":"controller_scaledobject","msg":"Detected ScaleType = Deployment","Request.Namespace":"default","Request.Name":"batch-processor-scaler"}
{"level":"error","ts":1588728541.819408,"logger":"azure_servicebus_scaler","msg":"error","error":"","stacktrace":"github.com/go-logr/zapr.(*zapLogger).Error\n\t/go/pkg/mod/github.com/go-logr/[email protected]/zapr.go:128\ngithub.com/kedacore/keda/pkg/scalers.(*azureServiceBusScaler).IsActive\n\tkeda/pkg/scalers/azure_servicebus_scaler.go:133\ngithub.com/kedacore/keda/pkg/handler.(*ScaleHandler).handleScaleDeployment\n\tkeda/pkg/handler/scale_loop.go:119\ngithub.com/kedacore/keda/pkg/handler.(*ScaleHandler).handleScale\n\tkeda/pkg/handler/scale_loop.go:45\ngithub.com/kedacore/keda/pkg/handler.(*ScaleHandler).HandleScaleLoop\n\tkeda/pkg/handler/scale_loop.go:14"}
{"level":"error","ts":1588728541.8435235,"logger":"scalehandler","msg":"Error updating deployment","ScaledObject.Namespace":"default","ScaledObject.Name":"batch-processor-scaler","ScaledObject.ScaleType":"deployment","Deployment.Namespace":"default","Deployment.Name":"batch-processor","error":"Operation cannot be fulfilled on deployments.apps \"batch-processor\": the object has been modified; please apply your changes to the latest version and try again","stacktrace":"github.com/go-logr/zapr.(*zapLogger).Error\n\t/go/pkg/mod/github.com/go-logr/[email protected]/zapr.go:128\ngithub.com/kedacore/keda/pkg/handler.(*ScaleHandler).updateDeployment\n\tkeda/pkg/handler/scale_deployments.go:58\ngithub.com/kedacore/keda/pkg/handler.(*ScaleHandler).scaleDeploymentToZero\n\tkeda/pkg/handler/scale_deployments.go:81\ngithub.com/kedacore/keda/pkg/handler.(*ScaleHandler).scaleDeployment\n\tkeda/pkg/handler/scale_deployments.go:29\ngithub.com/kedacore/keda/pkg/handler.(*ScaleHandler).handleScaleDeployment\n\tkeda/pkg/handler/scale_loop.go:130\ngithub.com/kedacore/keda/pkg/handler.(*ScaleHandler).handleScale\n\tkeda/pkg/handler/scale_loop.go:45\ngithub.com/kedacore/keda/pkg/handler.(*ScaleHandler).HandleScaleLoop\n\tkeda/pkg/handler/scale_loop.go:14"}
{"level":"info","ts":1588728556.8574846,"logger":"controller_scaledobject","msg":"Reconciling ScaledObject","Request.Namespace":"default","Request.Name":"batch-processor-scaler"}
{"level":"info","ts":1588728556.8575203,"logger":"controller_scaledobject","msg":"Detected ScaleType = Deployment","Request.Namespace":"default","Request.Name":"batch-processor-scaler"}
{"level":"error","ts":1588728572.834683,"logger":"azure_servicebus_scaler","msg":"error","error":"","stacktrace":"github.com/go-logr/zapr.(*zapLogger).Error\n\t/go/pkg/mod/github.com/go-logr/[email protected]/zapr.go:128\ngithub.com/kedacore/keda/pkg/scalers.(*azureServiceBusScaler).IsActive\n\tkeda/pkg/scalers/azure_servicebus_scaler.go:133\ngithub.com/kedacore/keda/pkg/handler.(*ScaleHandler).handleScaleDeployment\n\tkeda/pkg/handler/scale_loop.go:119\ngithub.com/kedacore/keda/pkg/handler.(*ScaleHandler).handleScale\n\tkeda/pkg/handler/scale_loop.go:45\ngithub.com/kedacore/keda/pkg/handler.(*ScaleHandler).HandleScaleLoop\n\tkeda/pkg/handler/scale_loop.go:28"}
{"level":"info","ts":1588728572.8433483,"logger":"scalehandler","msg":"Successfully scaled deployment to 0 replicas","ScaledObject.Namespace":"default","ScaledObject.Name":"batch-processor-scaler","ScaledObject.ScaleType":"deployment","Deployment.Namespace":"default","Deployment.Name":"batch-processor"}
{"level":"info","ts":1588728588.4522712,"logger":"controller_scaledobject","msg":"Reconciling ScaledObject","Request.Namespace":"default","Request.Name":"batch-processor-scaler"}
{"level":"info","ts":1588728588.4523873,"logger":"controller_scaledobject","msg":"Detected ScaleType = Deployment","Request.Namespace":"default","Request.Name":"batch-processor-scaler"}
{"level":"error","ts":1588728603.8379118,"logger":"azure_servicebus_scaler","msg":"error","error":"","stacktrace":"github.com/go-logr/zapr.(*zapLogger).Error\n\t/go/pkg/mod/github.com/go-logr/[email protected]/zapr.go:128\ngithub.com/kedacore/keda/pkg/scalers.(*azureServiceBusScaler).IsActive\n\tkeda/pkg/scalers/azure_servicebus_scaler.go:133\ngithub.com/kedacore/keda/pkg/handler.(*ScaleHandler).handleScaleDeployment\n\tkeda/pkg/handler/scale_loop.go:119\ngithub.com/kedacore/keda/pkg/handler.(*ScaleHandler).handleScale\n\tkeda/pkg/handler/scale_loop.go:45\ngithub.com/kedacore/keda/pkg/handler.(*ScaleHandler).HandleScaleLoop\n\tkeda/pkg/handler/scale_loop.go:28"}

The issue was I set SAS Policy to "Listen". I figured KEDA doesn't need to write to the message bus, so "Listen" seemed appropriate. Turned out it needs to be "Manage" permission.

Proposal

1. Document that SAS Policy has to have Manage permissions.
2. Make error logs useful for debugging this issue. Now it does not have any details other than there was some error in Service Bus scaler.
3. Do not scale down to 0 instances if there was an error connecting to Service Bus.

[tomkerkhove]

I thought this was clearly documented but apparently that's not the case - Thanks for reporting!

Are you open for creating a PR on https://github.com/kedacore/keda-docs for the docs?

[tomkerkhove]

@ahmelsayed Do you mind having a look at the log side please?

[tomkerkhove]

Thanks for reporting btw @programaka

[nzthiago]

@tomkerkhove why does it need a Manage policy? I can see how this could be a blocker for some customers giving Manage permissions allow creating and deleting queues/topics. Would be interesting for @programaka to start the docs PR and then expand with the explanation of the need for Manage in the doc as well.

[tomkerkhove]

Yes, it needs it unfortunately to get the metrics but that does not mean the deployment needs it so you can seperate auth concerns with our TriggerAuthentication model.

You can see it in action in our sample here but basically KEDA scales since it has Manage permissions via TriggerAuth but the deployment still runs with Listen permissions.

The alternative for KEDA is using Azure Monitor metrics but then you have the 5min delay which is less interesting imo.

Another alternative is Managed Identity which we also support.

Hope this helps/clarifies things.

[nzthiago]

@tomkerkhove thanks - that would also be good to include in the docs. @programaka perhaps include this detail in the docs PR as well? 👍

[programaka]

@nzthiago, @tomkerkhove I will create a PR for the docs

[ahmelsayed]

regarding the error message, this is what I see when the key doesn't have the proper scope

{
  "level":"error",
  "ts":1589951034.0498915,
  "logger":"azure_servicebus_scaler",
  "msg":"error",
  "error":"error code: 401, Details: Manage,EntityRead claims required for this operation. TrackingId:0b719874-3f1c-4247-9cf5-4b57cfd6635e_G24, SystemTracker:ahmelssbtest1.servicebus.windows.net:myinputqueue, Timestamp:2020-05-20T05:03:53","stacktrace":"github.com/go-logr/zapr.(*zapLogger).Error\n\t/home/ahmed/go/pkg/mod/github.com/go-logr/[email protected]/zapr.go:128\ngithub.com/kedacore/keda/pkg/scalers.(*azureServiceBusScaler).IsActive\n\t/home/ahmed/repos/keda-v2/pkg/scalers/azure_servicebus_scaler.go:134\ngithub.com/kedacore/keda/pkg/handler.(*ScaleHandler).handleScaleDeployment\n\t/home/ahmed/repos/keda-v2/pkg/handler/scale_loop.go:119\ngithub.com/kedacore/keda/pkg/handler.(*ScaleHandler).handleScale\n\t/home/ahmed/repos/keda-v2/pkg/handler/scale_loop.go:45\ngithub.com/kedacore/keda/pkg/handler.(*ScaleHandler).HandleScaleLoop\n\t/home/ahmed/repos/keda-v2/pkg/handler/scale_loop.go:28"
}

[tomkerkhove]

Perfect thanks for checking!

[programaka]

@ahmelsayed which logs are those? I looked at keda-operator logs and this message was not there. Was it recently added?

[ahmelsayed]

I tried to look through the changes, but couldn't find any changes that would have fixed this intentionally. But that's the log I see from kubectl logs <keda-operator-pod> -n keda when running 1.4.1 with a Listen only permission on the sb key. What version are you running?

[programaka]

1.4.1

[tomkerkhove]

Ok if we close this one @programaka ?

[programaka]

@tomkerkhove I am ok to close this one.