[🐛 BUG]: Can't cancel workflow from activity - UnhandledCommand for activity, but workflow is completed

egorzot commented 1 year ago

No duplicates 🥲.

[X] I have searched for a similar issue in our bug tracker and didn't find any solutions.

What happened?

I created an example for reproducing the behavior. A new CancelWorkflow with Activity that cancels that workflow (forked from https://github.com/temporalio/samples-php)

I am using the command: docker-compose exec app php app.php cancel-activity

Result:

the workflow is completed
workflow not canceled
activity with WorkflowTaskFailed in the temporal admin with message:

Cause : UnhandledCommand Failure: { "message": "UnhandledCommand", "source": "", "stackTrace": "", "encodedAttributes": null, "cause": null, "serverFailureInfo": { "nonRetryable": true } }

I'm expecting workflow canceling from the activity

Version

RoadRunner version: 2.12.3

Relevant log output

samples-php-app-1       | 2023-08-15T15:25:21.171Z      DEBUG   temporal        workflow execute        {"runID": "53f32eee-387e-478c-9d8b-c9f91d01099d", "workflow info": {"WorkflowExecution":{"ID":"wf-462","RunID":"53f32eee-387e-478c-9d8b-c9f91d01099d"},"WorkflowType":{"Name":"CancelActivity"},"TaskQueueName":"default","WorkflowExecutionTimeout":60000000000,"WorkflowRunTimeout":60000000000,"WorkflowTaskTimeout":10000000000,"Namespace":"default","Attempt":1,"WorkflowStartTime":"2023-08-15T15:25:21.141917945Z","CronSchedule":"","ContinuedExecutionRunID":"","ParentWorkflowNamespace":"","ParentWorkflowExecution":null,"Memo":null,"SearchAttributes":null,"RetryPolicy":null,"BinaryChecksum":"e3d02694289f74cc72ea990fe241278d"}}
samples-php-app-1       | 2023-08-15T15:25:21.171Z      DEBUG   temporal        workflow task started   {"time": "1s"}
samples-php-app-1       | 2023-08-15T15:25:21.171Z      DEBUG   temporal        outgoing message        {"id": 1, "data": "", "context": ""}
samples-php-app-1       | 2023-08-15T15:25:21.177Z      DEBUG   temporal        received message        {"command": {"name":"ActivityCancel.cancel","options":{"ActivityID":"","TaskQueueName":"","ScheduleToCloseTimeout":20000000000,"ScheduleToStartTimeout":0,"StartToCloseTimeout":0,"HeartbeatTimeout":0,"WaitForCancellation":false,"OriginalTaskQueueName":"","RetryPolicy":null,"DisableEagerExecution":false}}, "id": 9001, "data": "\n\ufffd\u0002\u0008\ufffdF\u0012\u000fExecuteActivity\u001a\ufffd\u0001{\"name\":\"ActivityCancel.cancel\",\"options\":{\"TaskQueueName\":null,\"ScheduleToCloseTimeout\":20000000000,\"ScheduleToStartTimeout\":0,\"StartToCloseTimeout\":0,\"HeartbeatTimeout\":0,\"WaitForCancellation\":false,\"ActivityID\":\"\",\"RetryPolicy\":null}}*$\n\"\n\u0016\n\u0008encoding\u0012\njson/plain\u0012\u0008\"wf-462\"\n\u001f\u0008\u0001*\u001b\n\u0019\n\u0017\n\u0008encoding\u0012\u000bbinary/null"}
samples-php-app-1       | 2023-08-15T15:25:21.177Z      DEBUG   temporal        received message        {"command": null, "id": 1, "data": "\n\ufffd\u0002\u0008\ufffdF\u0012\u000fExecuteActivity\u001a\ufffd\u0001{\"name\":\"ActivityCancel.cancel\",\"options\":{\"TaskQueueName\":null,\"ScheduleToCloseTimeout\":20000000000,\"ScheduleToStartTimeout\":0,\"StartToCloseTimeout\":0,\"HeartbeatTimeout\":0,\"WaitForCancellation\":false,\"ActivityID\":\"\",\"RetryPolicy\":null}}*$\n\"\n\u0016\n\u0008encoding\u0012\njson/plain\u0012\u0008\"wf-462\"\n\u001f\u0008\u0001*\u001b\n\u0019\n\u0017\n\u0008encoding\u0012\u000bbinary/null"}
samples-php-app-1       | 2023-08-15T15:25:21.177Z      DEBUG   temporal        activity request        {"ID": 9001}
samples-php-app-1       | 2023-08-15T15:25:21.177Z      DEBUG   temporal        ExecuteActivity {"Namespace": "default", "TaskQueue": "default", "WorkerID": "default:fdd90c6e-152a-4568-a0a2-d76fc3a8f7e8", "WorkflowType": "CancelActivity", "WorkflowID": "wf-462", "RunID": "53f32eee-387e-478c-9d8b-c9f91d01099d", "Attempt": 1, "ActivityID": "5", "ActivityType": "ActivityCancel.cancel"}
samples-php-app-1       | 2023-08-15T15:25:21.190Z      DEBUG   temporal        outgoing message        {"id": 1, "data": "", "context": ""}

samples-php-app-1       | 2023-08-15T15:25:21.195Z      INFO    server          [debug] Starting cancel activity.
samples-php-app-1       | 2023-08-15T15:25:21.198Z      INFO    server          [debug] created new workflowClient, get workflowID:wf-462
samples-php-app-1       | 2023-08-15T15:25:21.198Z      INFO    server          [debug] got workflow with ID:wf-462
samples-php-app-1       | 2023-08-15T15:25:21.210Z      INFO    server          [debug] cancelled workflow with ID:wf-462
samples-php-app-1       | 2023-08-15T15:25:21.210Z      DEBUG   temporal        received message        {"command": null, "id": 1, "data": "\n\u001f\u0008\u0001*\u001b\n\u0019\n\u0017\n\u0008encoding\u0012\u000bbinary/null"}
samples-php-app-1       | 2023-08-15T15:25:21.217Z      DEBUG   temporal        workflow task started   {"time": "1s"}
samples-php-app-1       | 2023-08-15T15:25:21.217Z      DEBUG   temporal        outgoing message        {"id": 2, "data": "", "context": ""}
samples-php-app-1       | 2023-08-15T15:25:21.217Z      DEBUG   temporal        received message        {"command": {"ids":[9001]}, "id": 9002, "data": "\n\u001d\u0008\ufffdF\u0012\u0006Cancel\u001a\u000e{\"ids\":[9001]}*\u0000\n\u001f\u0008\u0002*\u001b\n\u0019\n\u0017\n\u0008encoding\u0012\u000bbinary/null"}
samples-php-app-1       | 2023-08-15T15:25:21.217Z      DEBUG   temporal        received message        {"command": null, "id": 2, "data": "\n\u001d\u0008\ufffdF\u0012\u0006Cancel\u001a\u000e{\"ids\":[9001]}*\u0000\n\u001f\u0008\u0002*\u001b\n\u0019\n\u0017\n\u0008encoding\u0012\u000bbinary/null"}
samples-php-app-1       | 2023-08-15T15:25:21.217Z      DEBUG   temporal        cancel request  {"ID": 9002}
samples-php-app-1       | 2023-08-15T15:25:21.217Z      DEBUG   temporal        registering activity canceller  {"activityID": "5"}
samples-php-app-1       | 2023-08-15T15:25:21.217Z      DEBUG   temporal        calling callback IN LOOP        {"ID": 9001, "type": "activity"}
samples-php-app-1       | 2023-08-15T15:25:21.217Z      DEBUG   temporal        executing callback      {"ID": 9001, "type": "activity"}
samples-php-app-1       | 2023-08-15T15:25:21.217Z      DEBUG   temporal        error   {"error": "canceled", "type": "activity"}
samples-php-app-1       | 2023-08-15T15:25:21.217Z      DEBUG   temporal        RequestCancelActivity   {"Namespace": "default", "TaskQueue": "default", "WorkerID": "default:fdd90c6e-152a-4568-a0a2-d76fc3a8f7e8", "WorkflowType": "CancelActivity", "WorkflowID": "wf-462", "RunID": "53f32eee-387e-478c-9d8b-c9f91d01099d", "Attempt": 1, "ActivityID": "5"}
samples-php-app-1       | 2023-08-15T15:25:21.217Z      DEBUG   temporal        outgoing message        {"id": 9001, "data": "", "context": ""}
samples-php-app-1       | 2023-08-15T15:25:21.217Z      DEBUG   temporal        outgoing message        {"id": 9002, "data": "", "context": ""}
samples-php-app-1       | 2023-08-15T15:25:21.219Z      DEBUG   temporal        received message        {"command": {}, "id": 9003, "data": "\n\ufffd\u0002\u0008\ufffdF\u0012\u0010CompleteWorkflow\u001a\u0002{}\"\ufffd\u0002\n\u0008canceled\u0012\u0005GoSDK\u001a\ufffd\u0002/var/app/src/CancelActivity/CancelWorkflow.php:46\n/var/app/vendor/temporal/sdk/src/Worker/Worker.php:94\n/var/app/vendor/temporal/sdk/src/WorkerFactory.php:413\n/var/app/vendor/temporal/sdk/src/WorkerFactory.php:387\n/var/app/vendor/temporal/sdk/src/WorkerFactory.php:261\n/var/app/worker.php:47:\u0000*\u0000"}
samples-php-app-1       | 2023-08-15T15:25:21.219Z      DEBUG   temporal        complete workflow request       {"ID": 9003}
samples-php-app-1       | 2023-08-15T15:25:21.219Z      DEBUG   temporal        close workflow  {"RunID": "53f32eee-387e-478c-9d8b-c9f91d01099d"}
samples-php-app-1       | 2023-08-15T15:25:21.219Z      DEBUG   temporal        outgoing message        {"id": 3, "data": "", "context": ""}
samples-php-app-1       | 2023-08-15T15:25:21.219Z      DEBUG   temporal        received message        {"command": null, "id": 3, "data": "\n\u001f\u0008\u0003*\u001b\n\u0019\n\u0017\n\u0008encoding\u0012\u000bbinary/null"}
temporal                | {"level":"info","ts":"2023-08-15T15:25:21.220Z","msg":"Failing the workflow task.","shard-id":3,"address":"192.168.224.4:7234","component":"history-engine","value":"UnhandledCommand","wf-id":"wf-462","wf-run-id":"53f32eee-387e-478c-9d8b-c9f91d01099d","wf-namespace-id":"0ed8e308-3644-4697-92a7-689f941154ce","logging-call-at":"workflowTaskHandlerCallbacks.go:570"}
temporal                | {"level":"info","ts":"2023-08-15T15:25:21.227Z","msg":"history client encountered error","service":"frontend","error":"UnhandledCommand","service-error-type":"serviceerror.InvalidArgument","logging-call-at":"metric_client.go:104"}
samples-php-app-1       | 2023-08-15T15:25:21.227Z      INFO    temporal        Task processing failed with error       {"Namespace": "default", "TaskQueue": "default", "WorkerID": "default:fdd90c6e-152a-4568-a0a2-d76fc3a8f7e8", "WorkerType": "WorkflowWorker", "Error": "UnhandledCommand"}
samples-php-app-1       | 2023-08-15T15:25:21.234Z      DEBUG   temporal        workflow execute        {"runID": "53f32eee-387e-478c-9d8b-c9f91d01099d", "workflow info": {"WorkflowExecution":{"ID":"wf-462","RunID":"53f32eee-387e-478c-9d8b-c9f91d01099d"},"WorkflowType":{"Name":"CancelActivity"},"TaskQueueName":"default","WorkflowExecutionTimeout":60000000000,"WorkflowRunTimeout":60000000000,"WorkflowTaskTimeout":10000000000,"Namespace":"default","Attempt":1,"WorkflowStartTime":"2023-08-15T15:25:21.141917945Z","CronSchedule":"","ContinuedExecutionRunID":"","ParentWorkflowNamespace":"","ParentWorkflowExecution":null,"Memo":null,"SearchAttributes":null,"RetryPolicy":null,"BinaryChecksum":"e3d02694289f74cc72ea990fe241278d"}}
samples-php-app-1       | 2023-08-15T15:25:21.234Z      DEBUG   temporal        workflow task started   {"time": "1s"}
samples-php-app-1       | 2023-08-15T15:25:21.234Z      DEBUG   temporal        outgoing message        {"id": 4, "data": "", "context": ""}
samples-php-app-1       | 2023-08-15T15:25:21.235Z      DEBUG   temporal        received message        {"command": {"name":"ActivityCancel.cancel","options":{"ActivityID":"","TaskQueueName":"","ScheduleToCloseTimeout":20000000000,"ScheduleToStartTimeout":0,"StartToCloseTimeout":0,"HeartbeatTimeout":0,"WaitForCancellation":false,"OriginalTaskQueueName":"","RetryPolicy":null,"DisableEagerExecution":false}}, "id": 9004, "data": "\n\ufffd\u0002\u0008\ufffdF\u0012\u000fExecuteActivity\u001a\ufffd\u0001{\"name\":\"ActivityCancel.cancel\",\"options\":{\"TaskQueueName\":null,\"ScheduleToCloseTimeout\":20000000000,\"ScheduleToStartTimeout\":0,\"StartToCloseTimeout\":0,\"HeartbeatTimeout\":0,\"WaitForCancellation\":false,\"ActivityID\":\"\",\"RetryPolicy\":null}}*$\n\"\n\u0016\n\u0008encoding\u0012\njson/plain\u0012\u0008\"wf-462\"\n\u001f\u0008\u0004*\u001b\n\u0019\n\u0017\n\u0008encoding\u0012\u000bbinary/null"}
samples-php-app-1       | 2023-08-15T15:25:21.235Z      DEBUG   temporal        received message        {"command": null, "id": 4, "data": "\n\ufffd\u0002\u0008\ufffdF\u0012\u000fExecuteActivity\u001a\ufffd\u0001{\"name\":\"ActivityCancel.cancel\",\"options\":{\"TaskQueueName\":null,\"ScheduleToCloseTimeout\":20000000000,\"ScheduleToStartTimeout\":0,\"StartToCloseTimeout\":0,\"HeartbeatTimeout\":0,\"WaitForCancellation\":false,\"ActivityID\":\"\",\"RetryPolicy\":null}}*$\n\"\n\u0016\n\u0008encoding\u0012\njson/plain\u0012\u0008\"wf-462\"\n\u001f\u0008\u0004*\u001b\n\u0019\n\u0017\n\u0008encoding\u0012\u000bbinary/null"}
samples-php-app-1       | 2023-08-15T15:25:21.235Z      DEBUG   temporal        activity request        {"ID": 9004}
samples-php-app-1       | 2023-08-15T15:25:21.235Z      DEBUG   temporal        workflow task started   {"time": "1s"}
samples-php-app-1       | 2023-08-15T15:25:21.235Z      DEBUG   temporal        appending callback      {"ID": 9004, "type": "activity"}
samples-php-app-1       | 2023-08-15T15:25:21.235Z      DEBUG   temporal        executing callback      {"ID": 9004, "type": "activity"}
samples-php-app-1       | 2023-08-15T15:25:21.235Z      DEBUG   temporal        pushing response        {"ID": 9004, "type": "activity"}
samples-php-app-1       | 2023-08-15T15:25:21.235Z      DEBUG   temporal        outgoing message        {"id": 5, "data": "", "context": ""}
samples-php-app-1       | 2023-08-15T15:25:21.235Z      DEBUG   temporal        outgoing message        {"id": 9004, "data": "", "context": ""}
samples-php-app-1       | 2023-08-15T15:25:21.235Z      DEBUG   temporal        received message        {"command": {"ids":[9004]}, "id": 9005, "data": "\n\u001d\u0008\ufffdF\u0012\u0006Cancel\u001a\u000e{\"ids\":[9004]}*\u0000\n\u001f\u0008\u0005*\u001b\n\u0019\n\u0017\n\u0008encoding\u0012\u000bbinary/null\n6\u0008\ufffdF\u0012\u0010CompleteWorkflow\u001a\u0002{}*\u001b\n\u0019\n\u0017\n\u0008encoding\u0012\u000bbinary/null"}
samples-php-app-1       | 2023-08-15T15:25:21.235Z      DEBUG   temporal        received message        {"command": null, "id": 5, "data": "\n\u001d\u0008\ufffdF\u0012\u0006Cancel\u001a\u000e{\"ids\":[9004]}*\u0000\n\u001f\u0008\u0005*\u001b\n\u0019\n\u0017\n\u0008encoding\u0012\u000bbinary/null\n6\u0008\ufffdF\u0012\u0010CompleteWorkflow\u001a\u0002{}*\u001b\n\u0019\n\u0017\n\u0008encoding\u0012\u000bbinary/null"}
samples-php-app-1       | 2023-08-15T15:25:21.235Z      DEBUG   temporal        received message        {"command": {}, "id": 9006, "data": "\n\u001d\u0008\ufffdF\u0012\u0006Cancel\u001a\u000e{\"ids\":[9004]}*\u0000\n\u001f\u0008\u0005*\u001b\n\u0019\n\u0017\n\u0008encoding\u0012\u000bbinary/null\n6\u0008\ufffdF\u0012\u0010CompleteWorkflow\u001a\u0002{}*\u001b\n\u0019\n\u0017\n\u0008encoding\u0012\u000bbinary/null"}
samples-php-app-1       | 2023-08-15T15:25:21.235Z      DEBUG   temporal        cancel request  {"ID": 9005}
samples-php-app-1       | 2023-08-15T15:25:21.235Z      DEBUG   temporal        outgoing message        {"id": 9005, "data": "", "context": ""}
samples-php-app-1       | 2023-08-15T15:25:21.235Z      DEBUG   temporal        complete workflow request       {"ID": 9006}
samples-php-app-1       | 2023-08-15T15:25:21.235Z      DEBUG   temporal        close workflow  {"RunID": "53f32eee-387e-478c-9d8b-c9f91d01099d"}
samples-php-app-1       | 2023-08-15T15:25:21.235Z      DEBUG   temporal        outgoing message        {"id": 6, "data": "", "context": ""}
samples-php-app-1       | 2023-08-15T15:25:21.235Z      DEBUG   temporal        received message        {"command": null, "id": 6, "data": "\n\u001f\u0008\u0006*\u001b\n\u0019\n\u0017\n\u0008encoding\u0012\u000bbinary/null"}
temporal-ui             | {"time":"2023-08-15T15:25:23.327122692Z","id":"","remote_ip":"192.168.224.1","host":"localhost:8080","method":"GET","uri":"/_app/version.json","user_agent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/115.0.0.0 Safari/537.36","status":200,"error":"","latency":25261,"latency_human":"25.261µs","bytes_in":0,"bytes_out":27}
temporal-ui             | {"time":"2023-08-15T15:25:33.337458261Z","id":"","remote_ip":"192.168.224.1","host":"localhost:8080","method":"GET","uri":"/_app/version.json","user_agent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/115.0.0.0 Safari/537.36","status":200,"error":"","latency":59931,"latency_human":"59.931µs","bytes_in":0,"bytes_out":27}
temporal-ui             | {"time":"2023-08-15T15:25:43.34294232Z","id":"","remote_ip":"192.168.224.1","host":"localhost:8080","method":"GET","uri":"/_app/version.json","user_agent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/115.0.0.0 Safari/537.36","status":200,"error":"","latency":30211,"latency_human":"30.211µs","bytes_in":0,"bytes_out":27}
temporal                | {"level":"info","ts":"2023-08-15T15:25:49.020Z","msg":"none","service":"matching","component":"matching-engine","wf-task-queue-name":"/_sys/temporal-sys-batcher-taskqueue/1","wf-task-queue-type":"Activity","wf-namespace":"temporal-system","lifecycle":"Started","logging-call-at":"taskQueueManager.go:316"}
temporal                | {"level":"info","ts":"2023-08-15T15:25:49.023Z","msg":"none","service":"matching","component":"matching-engine","wf-task-queue-name":"/_sys/default-worker-tq/1","wf-task-queue-type":"Workflow","wf-namespace":"temporal-system","lifecycle":"Started","logging-call-at":"taskQueueManager.go:316"}

rustatian commented 1 year ago

Hey @egorzot 👋🏻 You're using outdated RR version which is not supported anymore. Please, retry this on a v2023.2.2.

rustatian commented 1 year ago

Also, what is your temporal/sdk version? (php-sdk)

roxblnfk commented 1 year ago

Hi @egorzot.

Try to add sleep(15); after the $workflow->cancel();

egorzot commented 1 year ago

Try to add sleep(15); after the $workflow->cancel();

@roxblnfk it works! Could you explain, please?

roxblnfk commented 1 year ago

There are two concurrent events: activity finishing and workflow cancelation.

After activity finish the WF will be closed without any event because there are no any action or condition to continue execution. And it just happens before the cancel event.

Using sleep() you freeze workflow execution and provide some time to Temporal to schedule and execute the Cancel event.

$workflow->cancel(); won't wait any close operation result from Temporal. It just will validate the workflow is existing and wasn't closed.

rustatian commented 1 year ago

Ok, since this is not a bug, I'm closing this issue. For tech support feel free to join temporal slack or SpiralScout discord server (https://discord.gg/spiralphp)

wolfy-j commented 1 year ago

In short: this is because the async nature of cancel call, code does not block on it since cancel might take a long time to complete (some cleanup activities for example).

The proper way to cancel workflow from inside the activity - return the result from activity that indicates the parent workflow that it has to be cancelled (i.e. NonRetryable error).

temporalio / roadrunner-temporal