search

Azure / dapr-workflows-aks-sample

Dapr workflows sample on AKS
Apache License 2.0
8 stars 8 forks source link

Task 'ReserveInventoryActivity' (#1) failed with an unhandled exception: Object reference not set to an instance of an object. #5

Open giuliohome opened 1 week ago

giuliohome commented 1 week ago

Installed on my Azure Kubernetes Cluster, following the instructions.

Getting

giulio@myhome:~/csharp/dapr-workflows-aks-sample/Deploy$ curl -X GET $APP_URL/stock/restock
giulio@myhome:~/csharp/dapr-workflows-aks-sample/Deploy$ curl -i -X POST $DAPR_URL/v1.0-beta1/workflows/dapr/OrderProcessingWorkflow/start?instanceID=1234 \
  -H "Content-Type: application/json" \
  -d '{ "input" : {"Name": "Paperclips", "TotalCost": 99.95, "Quantity": 1}}'
HTTP/1.1 202 Accepted
Content-Type: application/json
Traceparent: 00-00000000000000000000000000000000-0000000000000000-00
Date: Sat, 23 Nov 2024 11:48:14 GMT
Content-Length: 21

{"instanceID":"1234"}giulio@myhome:~/csharp/dapr-workflows-aks-sample/Deploy$ curl -i -X GET $DAPR_URL/v1.0-beta1/workflows/dapr/1234
HTTP/1.1 200 OK
Content-Type: application/json
Traceparent: 00-00000000000000000000000000000000-0000000000000000-00
Date: Sat, 23 Nov 2024 11:48:26 GMT
Content-Length: 580

{"instanceID":"1234","workflowName":"OrderProcessingWorkflow","createdAt":"2024-11-23T11:48:14.716034521Z","lastUpdatedAt":"2024-11-23T11:48:16.092827857Z","runtimeStatus":"FAILED","properties":{"dapr.workflow.custom_status":"","dapr.workflow.failure.error_message":"Task 'ReserveInventoryActivity' (#1) failed with an unhandled exception: Object reference not set to an instance of an object.","dapr.workflow.failure.error_type":"Microsoft.DurableTask.TaskFailedException","dapr.workflow.input":"{ \"input\" : {\"Name\": \"Paperclips\", \"TotalCost\": 99.95, \"Quantity\": 1}}"}}

After port-forwarding the dashboard service, the log from there also tracks ORCHESTRATION_STATUS_FAILED

2024-11-23T11:45:15.687Z  time="2024-11-23T11:45:15.687202821Z" level=info msg="work item stream established by user-agent: [grpc-dotnet/2.50.0 (.NET 7.0.4; CLR 7.0.4; net7.0; linux; x64)]" app_id=dwf-app instance=workflows-sample-6644c59b89-vd4f6 scope=dapr.runtime.wfengine type=log ver=1.14.4-msft.8
2024-11-23T11:45:15.687Z  time="2024-11-23T11:45:15.687254132Z" level=info msg="worker started with backend dapr.actors/v1-beta" app_id=dwf-app instance=workflows-sample-6644c59b89-vd4f6 scope=wfengine.durabletask.backend type=log ver=1.14.4-msft.8
2024-11-23T11:45:15.687Z  time="2024-11-23T11:45:15.687277369Z" level=info msg="Workflow engine started" app_id=dwf-app instance=workflows-sample-6644c59b89-vd4f6 scope=dapr.runtime.wfengine type=log ver=1.14.4-msft.8
2024-11-23T11:45:17.889Z  time="2024-11-23T11:45:17.889150083Z" level=info msg="Actor API level in the cluster has been updated to 10" app_id=dwf-app instance=workflows-sample-6644c59b89-vd4f6 scope=dapr.runtime.actor type=log ver=1.14.4-msft.8
2024-11-23T11:45:17.889Z  time="2024-11-23T11:45:17.889175293Z" level=info msg="Placement tables updated, version: 1" app_id=dwf-app instance=workflows-sample-6644c59b89-vd4f6 scope=dapr.runtime.actors.placement type=log ver=1.14.4-msft.8
2024-11-23T11:46:59.188Z  time="2024-11-23T11:46:59.188147056Z" level=info msg="gRPC API Called" app_id=dwf-app code=0 duration=0 instance=workflows-sample-6644c59b89-vd4f6 method=/dapr.proto.runtime.v1.Dapr/SaveState scope=dapr.runtime.grpc.api-info type=log useragent="grpc-dotnet/2.50.0 (.NET 7.0.4; CLR 7.0.4; net7.0; linux; x64) dapr-sdk-dotnet/v1.10.0+23ba7a278a816867a1b16e3d857754ba0f7f8d59" ver=1.14.4-msft.8
2024-11-23T11:46:59.193Z  time="2024-11-23T11:46:59.193211007Z" level=info msg="gRPC API Called" app_id=dwf-app code=0 duration=0 instance=workflows-sample-6644c59b89-vd4f6 method=/dapr.proto.runtime.v1.Dapr/SaveState scope=dapr.runtime.grpc.api-info type=log useragent="grpc-dotnet/2.50.0 (.NET 7.0.4; CLR 7.0.4; net7.0; linux; x64) dapr-sdk-dotnet/v1.10.0+23ba7a278a816867a1b16e3d857754ba0f7f8d59" ver=1.14.4-msft.8
2024-11-23T11:46:59.288Z  time="2024-11-23T11:46:59.287946652Z" level=info msg="gRPC API Called" app_id=dwf-app code=0 duration=0 instance=workflows-sample-6644c59b89-vd4f6 method=/dapr.proto.runtime.v1.Dapr/SaveState scope=dapr.runtime.grpc.api-info type=log useragent="grpc-dotnet/2.50.0 (.NET 7.0.4; CLR 7.0.4; net7.0; linux; x64) dapr-sdk-dotnet/v1.10.0+23ba7a278a816867a1b16e3d857754ba0f7f8d59" ver=1.14.4-msft.8
2024-11-23T11:48:14.717Z  time="2024-11-23T11:48:14.716934843Z" level=warning msg="Redis does not support transaction rollbacks and should not be used in production as an actor state store." app_id=dwf-app component="statestore (state.redis/v1)" instance=workflows-sample-6644c59b89-vd4f6 scope=dapr.contrib type=log ver=1.14.4-msft.8
2024-11-23T11:48:14.718Z  time="2024-11-23T11:48:14.718260431Z" level=info msg="HTTP API Called" app_id=dwf-app code=202 duration=2 instance=workflows-sample-6644c59b89-vd4f6 method="POST /v1.0-beta1/workflows/dapr/OrderProcessingWorkflow/start" scope=dapr.runtime.http-info size=21 type=log useragent=curl/8.2.1 ver=1.14.4-msft.8
2024-11-23T11:48:14.718Z  time="2024-11-23T11:48:14.718265465Z" level=info msg="1234: starting new 'OrderProcessingWorkflow' instance with ID = '1234'." app_id=dwf-app instance=workflows-sample-6644c59b89-vd4f6 scope=wfengine.durabletask.backend type=log ver=1.14.4-msft.8
2024-11-23T11:48:15.593Z  time="2024-11-23T11:48:15.59292121Z" level=info msg="gRPC API Called" app_id=dwf-app code=0 duration=0 instance=workflows-sample-6644c59b89-vd4f6 method=/TaskHubSidecarService/CompleteOrchestratorTask scope=dapr.runtime.grpc.api-info type=log useragent="grpc-dotnet/2.50.0 (.NET 7.0.4; CLR 7.0.4; net7.0; linux; x64)" ver=1.14.4-msft.8
2024-11-23T11:48:15.788Z  time="2024-11-23T11:48:15.788148702Z" level=info msg="gRPC API Called" app_id=dwf-app code=0 duration=0 instance=workflows-sample-6644c59b89-vd4f6 method=/TaskHubSidecarService/CompleteActivityTask scope=dapr.runtime.grpc.api-info type=log useragent="grpc-dotnet/2.50.0 (.NET 7.0.4; CLR 7.0.4; net7.0; linux; x64)" ver=1.14.4-msft.8
2024-11-23T11:48:15.892Z  time="2024-11-23T11:48:15.89273461Z" level=info msg="gRPC API Called" app_id=dwf-app code=0 duration=0 instance=workflows-sample-6644c59b89-vd4f6 method=/TaskHubSidecarService/CompleteOrchestratorTask scope=dapr.runtime.grpc.api-info type=log useragent="grpc-dotnet/2.50.0 (.NET 7.0.4; CLR 7.0.4; net7.0; linux; x64)" ver=1.14.4-msft.8
2024-11-23T11:48:15.992Z  time="2024-11-23T11:48:15.992130363Z" level=info msg="gRPC API Called" app_id=dwf-app code=0 duration=0 instance=workflows-sample-6644c59b89-vd4f6 method=/TaskHubSidecarService/CompleteActivityTask scope=dapr.runtime.grpc.api-info type=log useragent="grpc-dotnet/2.50.0 (.NET 7.0.4; CLR 7.0.4; net7.0; linux; x64)" ver=1.14.4-msft.8
2024-11-23T11:48:16.092Z  time="2024-11-23T11:48:16.092745205Z" level=info msg="gRPC API Called" app_id=dwf-app code=0 duration=0 instance=workflows-sample-6644c59b89-vd4f6 method=/TaskHubSidecarService/CompleteOrchestratorTask scope=dapr.runtime.grpc.api-info type=log useragent="grpc-dotnet/2.50.0 (.NET 7.0.4; CLR 7.0.4; net7.0; linux; x64)" ver=1.14.4-msft.8
2024-11-23T11:48:16.092Z  time="2024-11-23T11:48:16.092848853Z" level=info msg="1234: 'OrderProcessingWorkflow' completed with a FAILED status." app_id=dwf-app instance=workflows-sample-6644c59b89-vd4f6 scope=wfengine.durabletask.backend type=log ver=1.14.4-msft.8
2024-11-23T11:48:16.093Z  time="2024-11-23T11:48:16.093635987Z" level=info msg="Workflow Actor '1234': workflow completed with status 'ORCHESTRATION_STATUS_FAILED' workflowName 'OrderProcessingWorkflow'" app_id=dwf-app instance=workflows-sample-6644c59b89-vd4f6 scope=dapr.wfengine.backend.actors type=log ver=1.14.4-msft.8
2024-11-23T11:48:26.509Z  time="2024-11-23T11:48:26.509478774Z" level=info msg="1234: loaded 11 state records in 1.684971ms" app_id=dwf-app instance=workflows-sample-6644c59b89-vd4f6 scope=dapr.wfengine.backend.actors type=log ver=1.14.4-msft.8
2024-11-23T11:48:26.509Z  time="2024-11-23T11:48:26.509824619Z" level=info msg="HTTP API Called" app_id=dwf-app code=200 duration=2 instance=workflows-sample-6644c59b89-vd4f6 method="GET /v1.0-beta1/workflows/dapr/1234" scope=dapr.runtime.http-info size=580 type=log useragent=curl/8.2.1 ver=1.14.4-msft.8
giuliohome commented 1 week ago

Maybe more interesting the log from the workflows-sample container

2024-11-23T11:46:59.288Z  info: WorkflowSample.Controllers.StockController[0]
2024-11-23T11:46:59.288Z        Inventory Restocked!
2024-11-23T11:48:15.691Z  info: WorkflowSample.Activities.NotifyActivity[0]
2024-11-23T11:48:15.691Z        Received order 1234 for 1  at $0
2024-11-23T11:48:15.987Z  info: WorkflowSample.Activities.ReserveInventoryActivity[0]
2024-11-23T11:48:15.987Z        Reserving inventory for order '1234' of 1 (null)

Notice the null ... (and at $0! while it should be 99.5 I assume)

giuliohome commented 1 week ago

Same issue when running it locally (I've done a test without AKS but running on docker containers)

giulio@myhome:~/csharp/dapr-workflows-aks-sample$ dapr run --app-id dapr-aks-sample --dapr-http-port 3500 -- dotnet run
...
...
INFO[0009] Placement tables updated, version: 1          app_id=dapr-aks-sample instance=myhome scope=dapr.runtime.actors.placement type=log ver=1.14.4
== APP == warn: Microsoft.AspNetCore.HttpsPolicy.HttpsRedirectionMiddleware[3]
== APP ==       Failed to determine the https port for redirect.
== APP == info: WorkflowSample.Controllers.StockController[0]
== APP ==       Inventory Restocked!
WARN[0125] Redis does not support transaction rollbacks and should not be used in production as an actor state store.  app_id=dapr-aks-sample component="statestore (state.redis/v1)" instance=myhome scope=dapr.contrib type=log ver=1.14.4
INFO[0125] 1234: starting new 'OrderProcessingWorkflow' instance with ID = '1234'.  app_id=dapr-aks-sample instance=myhome scope=wfengine.durabletask.backend type=log ver=1.14.4
== APP == info: WorkflowSample.Activities.NotifyActivity[0]
== APP ==       Received order 1234 for 1  at $0
== APP == info: WorkflowSample.Activities.ReserveInventoryActivity[0]
== APP ==       Reserving inventory for order '1234' of 1 (null)
INFO[0126] 1234: 'OrderProcessingWorkflow' completed with a FAILED status.  app_id=dapr-aks-sample instance=myhome scope=wfengine.durabletask.backend type=log ver=1.14.4
INFO[0126] Workflow Actor '1234': workflow completed with status 'ORCHESTRATION_STATUS_FAILED' workflowName 'OrderProcessingWorkflow'  app_id=dapr-aks-sample instance=myhome scope=dapr.wfengine.backend.actors type=log ver=1.14.4
giuliohome commented 1 week ago

Here is the solution in the line below:

curl -i -X POST $DAPR_URL/v1.0-beta1/workflows/dapr/OrderProcessingWorkflow/start?instanceID=1234   -H "Content-Type: application/json" -d '{"Name": "Paperclips", "Cost": 99.95, "Quantity": 1}'

Will open a PR to fix the readme!

Tested also by installing the application in a different namespace of the AKS cluster. I found that it is important to change the redis namespace besides adding the namespace metadata in the Deploy yaml

helm install redis bitnami/redis --namespace myapp

Image