[Bug] Issues with sticky execution/queries/signals #170
Closed
Description
What are you really trying to do?
We've started a quite complex workflow with timers and signals in production, and faced with unstable behaviour: some workflow executions are OK, some lead to workers' crashes and stuck forever.
Describe the bug
After worker's restart the behaviour of queries and signals becomes unstable.
Minimal Reproduction
Test workflow:
#[WorkflowInterface]
class DummyWorkflow
{
private int $startAtTimestamp;
private bool $shouldStop = false;
#[WorkflowMethod]
#[ReturnType(Type::TYPE_STRING)]
public function start(): string|\Generator
{
$this->startAtTimestamp = Workflow::now()->getTimestamp();
yield Workflow::awaitWithTimeout(
120,
fn () => $this->shouldStop,
);
if ($this->shouldStop) {
return 'Stopped';
}
return 'Completed';
}
#[SignalMethod]
public function stop(): void
{
$this->shouldStop = true;
}
#[QueryMethod('payload')]
public function query(): object
{
return (object)[
'secondsFromStart' => time() - $this->startAtTimestamp,
];
}
}
Case 1: worker restart (e.g. after crash)
- Start workflow
- Reload workers with
rr reset
- Try to query workflow
tctl output:
$ tcl wf query -qt payload -w e5da1aee-a9fb-412b-9b96-35182203526b
Error: Query workflow failed.
Error Details: rpc error: code = InvalidArgument desc = workflow_process_handle_query: Workflow with the specified run identifier "effaf1ce-82d8-4bc3-b9df-f66fd2e9ca61" not found (type: LogicException, retryable: true)
Temporal log:
{"level":"error","ts":"2022-05-12T05:44:49.095Z","msg":"query directly though matching on sticky failed, will not attempt query on non-sticky","service":"history","shard-id":1,"address":"172.19.0.14:7234","shard-item":"0xc0004bac80","component":"history-engine","wf-namespace":"default","wf-id":"e5da1aee-a9fb-412b-9b96-35182203526b","wf-run-id":"55901692-8758-4870-a66a-a637d79d4698","wf-query-type":"payload","error":"workflow_process_handle_query: Workflow with the specified run identifier \"55901692-8758-4870-a66a-a637d79d4698\" not found (type: LogicException, retryable: true)","logging-call-at":"historyEngine.go:884","stacktrace":"go.temporal.io/server/common/log.(*zapLogger).Error\n\t/temporal/common/log/zap_logger.go:142\ngo.temporal.io/server/service/history.(*historyEngineImpl).queryDirectlyThroughMatching\n\t/temporal/service/history/historyEngine.go:884\ngo.temporal.io/server/service/history.(*historyEngineImpl).QueryWorkflow\n\t/temporal/service/history/historyEngine.go:790\ngo.temporal.io/server/service/history.(*Handler).QueryWorkflow.func1\n\t/temporal/service/history/handler.go:968\ngo.temporal.io/server/common/backoff.RetryContext\n\t/temporal/common/backoff/retry.go:125\ngo.temporal.io/server/service/history.(*Handler).QueryWorkflow\n\t/temporal/service/history/handler.go:966\ngo.temporal.io/server/api/historyservice/v1._HistoryService_QueryWorkflow_Handler.func1\n\t/temporal/api/historyservice/v1/service.pb.go:1401\ngo.temporal.io/server/common/rpc/interceptor.(*RateLimitInterceptor).Intercept\n\t/temporal/common/rpc/interceptor/rate_limit.go:83\ngoogle.golang.org/grpc.chainUnaryInterceptors.func1.1\n\t/go/pkg/mod/google.golang.org/grpc@v1.41.0/server.go:1113\ngo.temporal.io/server/common/rpc/interceptor.(*TelemetryInterceptor).Intercept\n\t/temporal/common/rpc/interceptor/telemetry.go:108\ngoogle.golang.org/grpc.chainUnaryInterceptors.func1.1\n\t/go/pkg/mod/google.golang.org/grpc@v1.41.0/server.go:1116\ngo.temporal.io/server/common/metrics.NewServerMetricsTrailerPropagatorInterceptor.func1\n\t/temporal/common/metrics/grpc.go:113\ngoogle.golang.org/grpc.chainUnaryInterceptors.func1.1\n\t/go/pkg/mod/google.golang.org/grpc@v1.41.0/server.go:1116\ngo.temporal.io/server/common/metrics.NewServerMetricsContextInjectorInterceptor.func1\n\t/temporal/common/metrics/grpc.go:66\ngoogle.golang.org/grpc.chainUnaryInterceptors.func1.1\n\t/go/pkg/mod/google.golang.org/grpc@v1.41.0/server.go:1116\ngo.temporal.io/server/common/rpc.ServiceErrorInterceptor\n\t/temporal/common/rpc/grpc.go:131\ngoogle.golang.org/grpc.chainUnaryInterceptors.func1.1\n\t/go/pkg/mod/google.golang.org/grpc@v1.41.0/server.go:1116\ngoogle.golang.org/grpc.chainUnaryInterceptors.func1\n\t/go/pkg/mod/google.golang.org/grpc@v1.41.0/server.go:1118\ngo.temporal.io/server/api/historyservice/v1._HistoryService_QueryWorkflow_Handler\n\t/temporal/api/historyservice/v1/service.pb.go:1403\ngoogle.golang.org/grpc.(*Server).processUnaryRPC\n\t/go/pkg/mod/google.golang.org/grpc@v1.41.0/server.go:1279\ngoogle.golang.org/grpc.(*Server).handleStream\n\t/go/pkg/mod/google.golang.org/grpc@v1.41.0/server.go:1608\ngoogle.golang.org/grpc.(*Server).serveStreams.func1.2\n\t/go/pkg/mod/google.golang.org/grpc@v1.41.0/server.go:923"}
Roadrunner log:
2022-05-12T05:44:49.078Z DEBUG temporal outgoing message {"data": "\nR\u0008\t\u0012\u000bInvokeQuery\u001aA{\"runId\":\"55901692-8758-4870-a66a-a637d79d4698\",\"name\":\"payload\"} {\"taskQueue\":\"default\",\"tickTime\":\"2022-05-12T05:44:20Z\"}"}
2022-05-12T05:44:49.094Z DEBUG temporal received message {"data": "\n\ufffd\r\u0008\t\"\ufffd\r\n[Workflow with the specified run identifier \"55901692-8758-4870-a66a-a637d79d4698\" not found\u0012\u0007PHP_SDK\u001a\ufffd\u000cLogicException: Workflow with the specified run identifier \"55901692-8758-4870-a66a-a637d79d4698\" not found in /opt/app/vendor/temporal/sdk/src/Internal/Transport/Router/WorkflowProcessAwareRoute.php:58\nStack trace:\n#0 /opt/app/vendor/temporal/sdk/src/Internal/Transport/Router/WorkflowProcessAwareRoute.php(44): Temporal\\Internal\\Transport\\Router\\WorkflowProcessAwareRoute->findProcessOrFail('55901692-8758-4...')\n#1 /opt/app/vendor/temporal/sdk/src/Internal/Transport/Router/InvokeQuery.php(55): Temporal\\Internal\\Transport\\Router\\WorkflowProcessAwareRoute->findInstanceOrFail('55901692-8758-4...')\n#2 /opt/app/vendor/temporal/sdk/src/Internal/Transport/Router.php(81): Temporal\\Internal\\Transport\\Router\\InvokeQuery->handle(Object(Temporal\\Worker\\Transport\\Command\\Request), Array, Object(React\\Promise\\Deferred))\n#3 /opt/app/vendor/temporal/sdk/src/Worker/Worker.php(93): Temporal\\Internal\\Transport\\Router->dispatch(Object(Temporal\\Worker\\Transport\\Command\\Request), Array)\n#4 /opt/app/vendor/temporal/sdk/src/WorkerFactory.php(413): Temporal\\Worker\\Worker->dispatch(Object(Temporal\\Worker\\Transport\\Command\\Request), Array)\n#5 /opt/app/vendor/temporal/sdk/src/Internal/Transport/Server.php(60): Temporal\\WorkerFactory->onRequest(Object(Temporal\\Worker\\Transport\\Command\\Request), Array)\n#6 /opt/app/vendor/temporal/sdk/src/WorkerFactory.php(387): Temporal\\Internal\\Transport\\Server->dispatch(Object(Temporal\\Worker\\Transport\\Command\\Request), Array)\n#7 /opt/app/vendor/temporal/sdk/src/WorkerFactory.php(261): Temporal\\WorkerFactory->dispatch('\\nR\\x08\\t\\x12\\vInvokeQue...', Array)\n#8 /opt/app/bin/worker(45): Temporal\\WorkerFactory->run()\n#9 {main}*\u0010\n\u000eLogicException"}
- Try to send signal
Web UI:
Signal has been written into event history, workflow tasks seems to be executed, but nothing actually happens (workflow continues to run):
Roadrunner log:
2022-05-12T05:48:07.728Z DEBUG temporal outgoing message {"data": "\nY\u0008\n\u0012\u000cInvokeSignal\u001aG{\"runId\":\"55901692-8758-4870-a66a-a637d79d4698\",\"name\":\"stop\"} {\"taskQueue\":\"default\",\"tickTime\":\"2022-05-12T05:48:07Z\"}"}
2022-05-12T05:48:07.730Z DEBUG temporal received message {"data": "\n\ufffd\r\u0008\n\"\ufffd\r\n[Workflow with the specified run identifier \"55901692-8758-4870-a66a-a637d79d4698\" not found\u0012\u0007PHP_SDK\u001a\ufffd\u000cLogicException: Workflow with the specified run identifier \"55901692-8758-4870-a66a-a637d79d4698\" not found in /opt/app/vendor/temporal/sdk/src/Internal/Transport/Router/WorkflowProcessAwareRoute.php:58\nStack trace:\n#0 /opt/app/vendor/temporal/sdk/src/Internal/Transport/Router/WorkflowProcessAwareRoute.php(44): Temporal\\Internal\\Transport\\Router\\WorkflowProcessAwareRoute->findProcessOrFail('55901692-8758-4...')\n#1 /opt/app/vendor/temporal/sdk/src/Internal/Transport/Router/InvokeSignal.php(45): Temporal\\Internal\\Transport\\Router\\WorkflowProcessAwareRoute->findInstanceOrFail('55901692-8758-4...')\n#2 /opt/app/vendor/temporal/sdk/src/Internal/Transport/Router.php(81): Temporal\\Internal\\Transport\\Router\\InvokeSignal->handle(Object(Temporal\\Worker\\Transport\\Command\\Request), Array, Object(React\\Promise\\Deferred))\n#3 /opt/app/vendor/temporal/sdk/src/Worker/Worker.php(93): Temporal\\Internal\\Transport\\Router->dispatch(Object(Temporal\\Worker\\Transport\\Command\\Request), Array)\n#4 /opt/app/vendor/temporal/sdk/src/WorkerFactory.php(413): Temporal\\Worker\\Worker->dispatch(Object(Temporal\\Worker\\Transport\\Command\\Request), Array)\n#5 /opt/app/vendor/temporal/sdk/src/Internal/Transport/Server.php(60): Temporal\\WorkerFactory->onRequest(Object(Temporal\\Worker\\Transport\\Command\\Request), Array)\n#6 /opt/app/vendor/temporal/sdk/src/WorkerFactory.php(387): Temporal\\Internal\\Transport\\Server->dispatch(Object(Temporal\\Worker\\Transport\\Command\\Request), Array)\n#7 /opt/app/vendor/temporal/sdk/src/WorkerFactory.php(261): Temporal\\WorkerFactory->dispatch('\\nY\\x08\\n\\x12\\fInvokeSig...', Array)\n#8 /opt/app/bin/worker(45): Temporal\\WorkerFactory->run()\n#9 {main}*\u0010\n\u000eLogicException"}
Case 2: roadrunner restarts (e.g. after redeploy)
- Start workflow
- Restart roadrunner server with
docker restart roadrunner_container
- Try to query workflow → got expected result
Temporal log:
{"level":"info","ts":"2022-05-12T05:59:19.961Z","msg":"query direct through matching failed on sticky, clearing sticky before attempting on non-sticky","service":"history","shard-id":1,"address":"172.19.0.14:7234","shard-item":"0xc0004bac80","component":"history-engine","wf-namespace":"default","wf-id":"teacher_16522_remove_slots","wf-run-id":"dccef09e-51f6-4a94-b852-48244932eccc","wf-query-type":"payload","logging-call-at":"historyEngine.go:893"}
{"level":"info","ts":"2022-05-12T05:59:19.961Z","msg":"query directly through matching on sticky timed out, attempting to query on non-sticky","service":"history","shard-id":1,"address":"172.19.0.14:7234","shard-item":"0xc0004bac80","component":"history-engine","wf-namespace":"default","wf-id":"teacher_16522_remove_slots","wf-run-id":"dccef09e-51f6-4a94-b852-48244932eccc","wf-query-type":"payload","wf-task-queue-name":"c55a0d6a348f:dcc25f94-63bf-4c1e-b42d-cc6e680fede9","wf-next-event-id":6,"logging-call-at":"historyEngine.go:923"}
Roadrunner log (workflow is replaying):
2022-05-12T05:59:19.965Z DEBUG temporal workflow execute {"runID": "dccef09e-51f6-4a94-b852-48244932eccc", "workflow info": {"WorkflowExecution":{"ID":"XXXXX","RunID":"dccef09e-51f6-4a94-b852-48244932eccc"},"WorkflowType":{"Name":"DummyWorkflow"},"TaskQueueName":"default","WorkflowExecutionTimeout":0,"WorkflowRunTimeout":0,"WorkflowTaskTimeout":10000000000,"Namespace":"default","Attempt":1,"WorkflowStartTime":"2022-05-12T05:57:38.056903166Z","CronSchedule":"","ContinuedExecutionRunID":"","ParentWorkflowNamespace":"","ParentWorkflowExecution":null,"Memo":null,"SearchAttributes":{"indexed_fields":{"SkyTeacherId":{"metadata":{"encoding":"anNvbi9wbGFpbg==","type":"SW50"},"data":"MTY1MjI="}}},"BinaryChecksum":"366aad4717fdb22d55eebef7c454528a"}}
2022-05-12T05:59:19.965Z DEBUG temporal sequenceID {"before": 0}
2022-05-12T05:59:19.965Z DEBUG temporal sequenceID {"after": 1}
2022-05-12T05:59:19.965Z DEBUG temporal workflow task started {"time": "1s"}
2022-05-12T05:59:19.966Z DEBUG temporal outgoing message {"data": "\n\ufffd\u0006\u0008\u0001\u0012\rStartWorkflow\u001a\ufffd\u0005{\"info\":{\"WorkflowExecution\":{\"ID\":\"teacher_16522_remove_slots\",\"RunID\":\"dccef09e-51f6-4a94-b852-48244932eccc\"},\"WorkflowType\":{\"Name\":\"DummyWorkflow\"},\"TaskQueueName\":\"default\",\"WorkflowExecutionTimeout\":0,\"WorkflowRunTimeout\":0,\"WorkflowTaskTimeout\":10000000000,\"Namespace\":\"default\",\"Attempt\":1,\"WorkflowStartTime\":\"2022-05-12T05:57:38.056903166Z\",\"CronSchedule\":\"\",\"ContinuedExecutionRunID\":\"\",\"ParentWorkflowNamespace\":\"\",\"ParentWorkflowExecution\":null,\"Memo\":null,\"SearchAttributes\":{\"indexed_fields\":{\"SkyTeacherId\":{\"metadata\":{\"encoding\":\"anNvbi9wbGFpbg==\",\"type\":\"SW50\"},\"data\":\"MTY1MjI=\"}}},\"BinaryChecksum\":\"366aad4717fdb22d55eebef7c454528a\"}}*D\n\u001f\n\u0016\n\u0008encoding\u0012\njson/plain\u0012\u000516522\n!\n\u0016\n\u0008encoding\u0012\njson/plain\u0012\u00072592000 {\"taskQueue\":\"default\",\"tickTime\":\"2022-05-12T05:57:38Z\",\"replay\":true}"}
2022-05-12T05:59:19.979Z DEBUG temporal received message {"data": "\n\"\u0008\ufffdF\u0012\u0008NewTimer\u001a\u0011{\"ms\":2592000000}*\u0000\n\u001f\u0008\u0001*\u001b\n\u0019\n\u0017\n\u0008encoding\u0012\u000bbinary/null"}
2022-05-12T05:59:19.979Z DEBUG temporal sequenceID {"before": 1}
2022-05-12T05:59:19.979Z DEBUG temporal sequenceID {"after": 2}
2022-05-12T05:59:19.979Z DEBUG temporal outgoing message {"data": "\nR\u0008\u0002\u0012\u000bInvokeQuery\u001aA{\"runId\":\"dccef09e-51f6-4a94-b852-48244932eccc\",\"name\":\"payload\"} {\"taskQueue\":\"default\",\"tickTime\":\"2022-05-12T05:57:38Z\",\"replay\":true}"}
2022-05-12T05:59:19.983Z DEBUG temporal received message {"data": "\nd\u0008\u0002*`\n^\n\u0016\n\u0008encoding\u0012\njson/plain\u0012D{\"teacherId\":16522,\"removalScheduledOn\":\"2022-06-11T05:57:38+00:00\"}"}
- Try to query workflow again → got
context deadline exceeded
error
Temporal log:
{"level":"info","ts":"2022-05-12T06:04:51.831Z","msg":"query directly through matching on sticky timed out, attempting to query on non-sticky","service":"history","shard-id":1,"address":"172.19.0.14:7234","shard-item":"0xc0004bac80","component":"history-engine","wf-namespace":"default","wf-id":"XXX","wf-run-id":"dccef09e-51f6-4a94-b852-48244932eccc","wf-query-type":"payload","wf-task-queue-name":"","wf-next-event-id":6,"logging-call-at":"historyEngine.go:923"}
{"level":"error","ts":"2022-05-12T06:05:21.830Z","msg":"query directly though matching on non-sticky failed","service":"history","shard-id":1,"address":"172.19.0.14:7234","shard-item":"0xc0004bac80","component":"history-engine","wf-namespace":"default","wf-id":"XXX","wf-run-id":"dccef09e-51f6-4a94-b852-48244932eccc","wf-query-type":"payload","error":"context deadline exceeded","logging-call-at":"historyEngine.go:941","stacktrace":"go.temporal.io/server/common/log.(*zapLogger).Error\n\t/temporal/common/log/zap_logger.go:142\ngo.temporal.io/server/service/history.(*historyEngineImpl).queryDirectlyThroughMatching\n\t/temporal/service/history/historyEngine.go:941\ngo.temporal.io/server/service/history.(*historyEngineImpl).QueryWorkflow\n\t/temporal/service/history/historyEngine.go:790\ngo.temporal.io/server/service/history.(*Handler).QueryWorkflow.func1\n\t/temporal/service/history/handler.go:968\ngo.temporal.io/server/common/backoff.RetryContext\n\t/temporal/common/backoff/retry.go:125\ngo.temporal.io/server/service/history.(*Handler).QueryWorkflow\n\t/temporal/service/history/handler.go:966\ngo.temporal.io/server/api/historyservice/v1._HistoryService_QueryWorkflow_Handler.func1\n\t/temporal/api/historyservice/v1/service.pb.go:1401\ngo.temporal.io/server/common/rpc/interceptor.(*RateLimitInterceptor).Intercept\n\t/temporal/common/rpc/interceptor/rate_limit.go:83\ngoogle.golang.org/grpc.chainUnaryInterceptors.func1.1\n\t/go/pkg/mod/google.golang.org/grpc@v1.41.0/server.go:1113\ngo.temporal.io/server/common/rpc/interceptor.(*TelemetryInterceptor).Intercept\n\t/temporal/common/rpc/interceptor/telemetry.go:108\ngoogle.golang.org/grpc.chainUnaryInterceptors.func1.1\n\t/go/pkg/mod/google.golang.org/grpc@v1.41.0/server.go:1116\ngo.temporal.io/server/common/metrics.NewServerMetricsTrailerPropagatorInterceptor.func1\n\t/temporal/common/metrics/grpc.go:113\ngoogle.golang.org/grpc.chainUnaryInterceptors.func1.1\n\t/go/pkg/mod/google.golang.org/grpc@v1.41.0/server.go:1116\ngo.temporal.io/server/common/metrics.NewServerMetricsContextInjectorInterceptor.func1\n\t/temporal/common/metrics/grpc.go:66\ngoogle.golang.org/grpc.chainUnaryInterceptors.func1.1\n\t/go/pkg/mod/google.golang.org/grpc@v1.41.0/server.go:1116\ngo.temporal.io/server/common/rpc.ServiceErrorInterceptor\n\t/temporal/common/rpc/grpc.go:131\ngoogle.golang.org/grpc.chainUnaryInterceptors.func1.1\n\t/go/pkg/mod/google.golang.org/grpc@v1.41.0/server.go:1116\ngoogle.golang.org/grpc.chainUnaryInterceptors.func1\n\t/go/pkg/mod/google.golang.org/grpc@v1.41.0/server.go:1118\ngo.temporal.io/server/api/historyservice/v1._HistoryService_QueryWorkflow_Handler\n\t/temporal/api/historyservice/v1/service.pb.go:1403\ngoogle.golang.org/grpc.(*Server).processUnaryRPC\n\t/go/pkg/mod/google.golang.org/grpc@v1.41.0/server.go:1279\ngoogle.golang.org/grpc.(*Server).handleStream\n\t/go/pkg/mod/google.golang.org/grpc@v1.41.0/server.go:1608\ngoogle.golang.org/grpc.(*Server).serveStreams.func1.2\n\t/go/pkg/mod/google.golang.org/grpc@v1.41.0/server.go:923"}
Roadrunner log:
2022-05-12T06:04:51.834Z DEBUG temporal workflow execute {"runID": "dccef09e-51f6-4a94-b852-48244932eccc", "workflow info": {"WorkflowExecution":{"ID":"XXX","RunID":"dccef09e-51f6-4a94-b852-48244932eccc"},"WorkflowType":{"Name":"DummyWorkflow"},"TaskQueueName":"default","WorkflowExecutionTimeout":0,"WorkflowRunTimeout":0,"WorkflowTaskTimeout":10000000000,"Namespace":"default","Attempt":1,"WorkflowStartTime":"2022-05-12T05:57:38.056903166Z","CronSchedule":"","ContinuedExecutionRunID":"","ParentWorkflowNamespace":"","ParentWorkflowExecution":null,"Memo":null,"SearchAttributes":{"indexed_fields":{"SkyTeacherId":{"metadata":{"encoding":"anNvbi9wbGFpbg==","type":"SW50"},"data":"MTY1MjI="}}},"BinaryChecksum":"366aad4717fdb22d55eebef7c454528a"}}
2022-05-12T06:04:51.834Z DEBUG temporal sequenceID {"before": 2}
2022-05-12T06:04:51.834Z DEBUG temporal sequenceID {"after": 3}
2022-05-12T06:04:51.834Z DEBUG temporal workflow task started {"time": "1s"}
2022-05-12T06:04:51.834Z DEBUG temporal outgoing message {"data": "\n\ufffd\u0006\u0008\u0003\u0012\rStartWorkflow\u001a\ufffd\u0005{\"info\":{\"WorkflowExecution\":{\"ID\":\"XXX\",\"RunID\":\"dccef09e-51f6-4a94-b852-48244932eccc\"},\"WorkflowType\":{\"Name\":\"DummyWorkflow\"},\"TaskQueueName\":\"default\",\"WorkflowExecutionTimeout\":0,\"WorkflowRunTimeout\":0,\"WorkflowTaskTimeout\":10000000000,\"Namespace\":\"default\",\"Attempt\":1,\"WorkflowStartTime\":\"2022-05-12T05:57:38.056903166Z\",\"CronSchedule\":\"\",\"ContinuedExecutionRunID\":\"\",\"ParentWorkflowNamespace\":\"\",\"ParentWorkflowExecution\":null,\"Memo\":null,\"SearchAttributes\":{\"indexed_fields\":{\"SkyTeacherId\":{\"metadata\":{\"encoding\":\"anNvbi9wbGFpbg==\",\"type\":\"SW50\"},\"data\":\"MTY1MjI=\"}}},\"BinaryChecksum\":\"366aad4717fdb22d55eebef7c454528a\"}}*D\n\u001f\n\u0016\n\u0008encoding\u0012\njson/plain\u0012\u000516522\n!\n\u0016\n\u0008encoding\u0012\njson/plain\u0012\u00072592000 {\"taskQueue\":\"default\",\"tickTime\":\"2022-05-12T05:57:38Z\",\"replay\":true}"}
2022-05-12T06:04:51.837Z DEBUG temporal received message {"data": "\n\ufffd\u000c\u0008\u0003\"\ufffd\u000c\n{Workflow \"DummyWorkflow\" with run id \"dccef09e-51f6-4a94-b852-48244932eccc\" has been already started\u0012\u0007PHP_SDK\u001a\ufffd\u000bLogicException: Workflow \"DummyWorkflow\" with run id \"dccef09e-51f6-4a94-b852-48244932eccc\" has been already started in /opt/app/vendor/temporal/sdk/src/Internal/Transport/Router/StartWorkflow.php:95\nStack trace:\n#0 /opt/app/vendor/temporal/sdk/src/Internal/Transport/Router/StartWorkflow.php(63): Temporal\\Internal\\Transport\\Router\\StartWorkflow->findWorkflowOrFail(Object(Temporal\\Workflow\\WorkflowInfo))\n#1 /opt/app/vendor/temporal/sdk/src/Internal/Transport/Router.php(81): Temporal\\Internal\\Transport\\Router\\StartWorkflow->handle(Object(Temporal\\Worker\\Transport\\Command\\Request), Array, Object(React\\Promise\\Deferred))\n#2 /opt/app/vendor/temporal/sdk/src/Worker/Worker.php(93): Temporal\\Internal\\Transport\\Router->dispatch(Object(Temporal\\Worker\\Transport\\Command\\Request), Array)\n#3 /opt/app/vendor/temporal/sdk/src/WorkerFactory.php(413): Temporal\\Worker\\Worker->dispatch(Object(Temporal\\Worker\\Transport\\Command\\Request), Array)\n#4 /opt/app/vendor/temporal/sdk/src/Internal/Transport/Server.php(60): Temporal\\WorkerFactory->onRequest(Object(Temporal\\Worker\\Transport\\Command\\Request), Array)\n#5 /opt/app/vendor/temporal/sdk/src/WorkerFactory.php(387): Temporal\\Internal\\Transport\\Server->dispatch(Object(Temporal\\Worker\\Transport\\Command\\Request), Array)\n#6 /opt/app/vendor/temporal/sdk/src/WorkerFactory.php(261): Temporal\\WorkerFactory->dispatch('\\n\\x80\\x06\\x08\\x03\\x12\\rStartWor...', Array)\n#7 /opt/app/bin/worker(45): Temporal\\WorkerFactory->run()\n#8 {main}*\u0010\n\u000eLogicException"}
2022-05-12T06:04:51.837Z ERROR temporal Workflow panic {"Namespace": "default", "TaskQueue": "default", "WorkerID": "default:7ddcc910-a81a-4d88-95bc-7eda895b5b91", "WorkflowType": "DummyWorkflow", "WorkflowID": "XXX", "RunID": "dccef09e-51f6-4a94-b852-48244932eccc", "Attempt": 1, "Error": "unknown command CommandType: Timer, ID: 5, possible causes are nondeterministic workflow definition code or incompatible change in the workflow definition", "StackTrace": "process event for default [panic]:\ngithub.com/spiral/sdk-go/internal.panicIllegalState(...)\n\tgithub.com/spiral/sdk-go@v1.12.0/internal/internal_decision_state_machine.go:395\ngithub.com/spiral/sdk-go/internal.(*commandsHelper).getCommand(0x0, {0x0, {0x26565e8, 0xc000d11950}})\n\tgithub.com/spiral/sdk-go@v1.12.0/internal/internal_decision_state_machine.go:856 +0x119\ngithub.com/spiral/sdk-go/internal.(*commandsHelper).handleTimerStarted(0xc000145260, {0x26565e8, 0xc00007cfb0})\n\tgithub.com/spiral/sdk-go@v1.12.0/internal/internal_decision_state_machine.go:1250 +0x29\ngithub.com/spiral/sdk-go/internal.(*workflowExecutionEventHandlerImpl).ProcessEvent(0xc0000e5080, 0xc000aaa4c0, 0xc0, 0x0)\n\tgithub.com/spiral/sdk-go@v1.12.0/internal/internal_event_handlers.go:833 +0x3fd\ngithub.com/spiral/sdk-go/internal.(*workflowExecutionContextImpl).ProcessWorkflowTask(0xc00015ca10, 0xc000a2c540)\n\tgithub.com/spiral/sdk-go@v1.12.0/internal/internal_task_handlers.go:874 +0xca8\ngithub.com/spiral/sdk-go/internal.(*workflowTaskHandlerImpl).ProcessWorkflowTask(0xc00019a580, 0xc000a2c540, 0xc0009eb6b0)\n\tgithub.com/spiral/sdk-go@v1.12.0/internal/internal_task_handlers.go:723 +0x493\ngithub.com/spiral/sdk-go/internal.(*workflowTaskPoller).processWorkflowTask(0xc0000d51e0, 0xc000a2c540)\n\tgithub.com/spiral/sdk-go@v1.12.0/internal/internal_task_pollers.go:284 +0x2cd\ngithub.com/spiral/sdk-go/internal.(*workflowTaskPoller).ProcessTask(0xc0000d51e0, {0x1594180, 0xc000a2c540})\n\tgithub.com/spiral/sdk-go@v1.12.0/internal/internal_task_pollers.go:255 +0x6c\ngithub.com/spiral/sdk-go/internal.(*baseWorker).processTask(0xc000185000, {0x1593d40, 0xc000520cc0})\n\tgithub.com/spiral/sdk-go@v1.12.0/internal/internal_worker_base.go:362 +0x167\ncreated by github.com/spiral/sdk-go/internal.(*baseWorker).runTaskDispatcher\n\tgithub.com/spiral/sdk-go@v1.12.0/internal/internal_worker_base.go:282 +0xba"}
2022-05-12T06:04:51.837Z DEBUG temporal sequenceID {"before": 3}
2022-05-12T06:04:51.837Z DEBUG temporal sequenceID {"after": 4}
2022-05-12T06:04:51.837Z DEBUG temporal outgoing message {"data": "\nE\u0008\u0004\u0012\u000fDestroyWorkflow\u001a0{\"runId\":\"dccef09e-51f6-4a94-b852-48244932eccc\"} {\"taskQueue\":\"default\",\"tickTime\":\"2022-05-12T05:57:38Z\",\"replay\":true}"}
2022-05-12T06:04:51.838Z DEBUG temporal received message {"data": "\n\u001f\u0008\u0004*\u001b\n\u0019\n\u0017\n\u0008encoding\u0012\u000bbinary/null"}
2022-05-12T06:04:51.838Z WARN temporal Failed to process workflow task. {"Namespace": "default", "TaskQueue": "default", "WorkerID": "default:7ddcc910-a81a-4d88-95bc-7eda895b5b91", "WorkflowType": "DummyWorkflow", "WorkflowID": "XXX", "RunID": "dccef09e-51f6-4a94-b852-48244932eccc", "Attempt": 1, "Error": "unknown command CommandType: Timer, ID: 5, possible causes are nondeterministic workflow definition code or incompatible change in the workflow definition"}
2022-05-12T06:04:51.840Z INFO temporal Task processing failed with error {"Namespace": "default", "TaskQueue": "default", "WorkerID": "default:7ddcc910-a81a-4d88-95bc-7eda895b5b91", "WorkerType": "WorkflowWorker", "Error": "Workflow executionsRow not found. WorkflowId: default, RunId: 1620e0fd-7a80-4d11-acfb-bb1fe4a509f3"}
If we continue making queries, we'll again get OK answer, then context deadline exceeded
error, etc.
- Try to query again and get expected answer
- Try to send signal7.
Web UI:
Signal is processed correctly, but after an error:
Roadrunner log:
2022-05-12T06:15:35.240Z DEBUG temporal workflow execute {"runID": "5a1bfd24-70e9-4cef-863e-5a2f0377223c", "workflow info": {"WorkflowExecution":{"ID":"XXX","RunID":"5a1bfd24-70e9-4cef-863e-5a2f0377223c"},"WorkflowType":{"Name":"DummyWorkflow"},"TaskQueueName":"default","WorkflowExecutionTimeout":0,"WorkflowRunTimeout":0,"WorkflowTaskTimeout":10000000000,"Namespace":"default","Attempt":1,"WorkflowStartTime":"2022-05-12T06:14:46.868631545Z","CronSchedule":"","ContinuedExecutionRunID":"","ParentWorkflowNamespace":"","ParentWorkflowExecution":null,"Memo":null,"SearchAttributes":{"indexed_fields":{"SkyTeacherId":{"metadata":{"encoding":"anNvbi9wbGFpbg==","type":"SW50"},"data":"MTY1MjI="}}},"BinaryChecksum":"366aad4717fdb22d55eebef7c454528a"}}
2022-05-12T06:15:35.240Z DEBUG temporal sequenceID {"before": 2}
2022-05-12T06:15:35.240Z DEBUG temporal sequenceID {"after": 3}
2022-05-12T06:15:35.240Z DEBUG temporal workflow task started {"time": "1s"}
2022-05-12T06:15:35.240Z DEBUG temporal outgoing message {"data": "\n\ufffd\u0006\u0008\u0003\u0012\rStartWorkflow\u001a\ufffd\u0005{\"info\":{\"WorkflowExecution\":{\"ID\":\"XXX\",\"RunID\":\"5a1bfd24-70e9-4cef-863e-5a2f0377223c\"},\"WorkflowType\":{\"Name\":\"DummyWorkflow\"},\"TaskQueueName\":\"default\",\"WorkflowExecutionTimeout\":0,\"WorkflowRunTimeout\":0,\"WorkflowTaskTimeout\":10000000000,\"Namespace\":\"default\",\"Attempt\":1,\"WorkflowStartTime\":\"2022-05-12T06:14:46.868631545Z\",\"CronSchedule\":\"\",\"ContinuedExecutionRunID\":\"\",\"ParentWorkflowNamespace\":\"\",\"ParentWorkflowExecution\":null,\"Memo\":null,\"SearchAttributes\":{\"indexed_fields\":{\"SkyTeacherId\":{\"metadata\":{\"encoding\":\"anNvbi9wbGFpbg==\",\"type\":\"SW50\"},\"data\":\"MTY1MjI=\"}}},\"BinaryChecksum\":\"366aad4717fdb22d55eebef7c454528a\"}}*D\n\u001f\n\u0016\n\u0008encoding\u0012\njson/plain\u0012\u000516522\n!\n\u0016\n\u0008encoding\u0012\njson/plain\u0012\u00072592000 {\"taskQueue\":\"default\",\"tickTime\":\"2022-05-12T06:14:46Z\",\"replay\":true}"}
2022-05-12T06:15:35.243Z DEBUG temporal received message {"data": "\n\ufffd\u000c\u0008\u0003\"\ufffd\u000c\n{Workflow \"DummyWorkflow\" with run id \"5a1bfd24-70e9-4cef-863e-5a2f0377223c\" has been already started\u0012\u0007PHP_SDK\u001a\ufffd\u000bLogicException: Workflow \"DummyWorkflow\" with run id \"5a1bfd24-70e9-4cef-863e-5a2f0377223c\" has been already started in /opt/app/vendor/temporal/sdk/src/Internal/Transport/Router/StartWorkflow.php:95\nStack trace:\n#0 /opt/app/vendor/temporal/sdk/src/Internal/Transport/Router/StartWorkflow.php(63): Temporal\\Internal\\Transport\\Router\\StartWorkflow->findWorkflowOrFail(Object(Temporal\\Workflow\\WorkflowInfo))\n#1 /opt/app/vendor/temporal/sdk/src/Internal/Transport/Router.php(81): Temporal\\Internal\\Transport\\Router\\StartWorkflow->handle(Object(Temporal\\Worker\\Transport\\Command\\Request), Array, Object(React\\Promise\\Deferred))\n#2 /opt/app/vendor/temporal/sdk/src/Worker/Worker.php(93): Temporal\\Internal\\Transport\\Router->dispatch(Object(Temporal\\Worker\\Transport\\Command\\Request), Array)\n#3 /opt/app/vendor/temporal/sdk/src/WorkerFactory.php(413): Temporal\\Worker\\Worker->dispatch(Object(Temporal\\Worker\\Transport\\Command\\Request), Array)\n#4 /opt/app/vendor/temporal/sdk/src/Internal/Transport/Server.php(60): Temporal\\WorkerFactory->onRequest(Object(Temporal\\Worker\\Transport\\Command\\Request), Array)\n#5 /opt/app/vendor/temporal/sdk/src/WorkerFactory.php(387): Temporal\\Internal\\Transport\\Server->dispatch(Object(Temporal\\Worker\\Transport\\Command\\Request), Array)\n#6 /opt/app/vendor/temporal/sdk/src/WorkerFactory.php(261): Temporal\\WorkerFactory->dispatch('\\n\\x80\\x06\\x08\\x03\\x12\\rStartWor...', Array)\n#7 /opt/app/bin/worker(45): Temporal\\WorkerFactory->run()\n#8 {main}*\u0010\n\u000eLogicException"}
2022-05-12T06:15:35.243Z ERROR temporal Workflow panic {"Namespace": "default", "TaskQueue": "default", "WorkerID": "default:4fe939cb-4f79-47c6-a1e9-8b6dad29ef7f", "WorkflowType": "DummyWorkflow", "WorkflowID": "XXX", "RunID": "5a1bfd24-70e9-4cef-863e-5a2f0377223c", "Attempt": 1, "Error": "unknown command CommandType: Timer, ID: 5, possible causes are nondeterministic workflow definition code or incompatible change in the workflow definition", "StackTrace": "process event for default [panic]:\ngithub.com/spiral/sdk-go/internal.panicIllegalState(...)\n\tgithub.com/spiral/sdk-go@v1.12.0/internal/internal_decision_state_machine.go:395\ngithub.com/spiral/sdk-go/internal.(*commandsHelper).getCommand(0x0, {0x0, {0x26565e8, 0x7fcb0d7c0228}})\n\tgithub.com/spiral/sdk-go@v1.12.0/internal/internal_decision_state_machine.go:856 +0x119\ngithub.com/spiral/sdk-go/internal.(*commandsHelper).handleTimerStarted(0x7fcb346c15b8, {0x26565e8, 0xc0005b4000})\n\tgithub.com/spiral/sdk-go@v1.12.0/internal/internal_decision_state_machine.go:1250 +0x29\ngithub.com/spiral/sdk-go/internal.(*workflowExecutionEventHandlerImpl).ProcessEvent(0xc00079e750, 0xc000918e00, 0xc0, 0x0)\n\tgithub.com/spiral/sdk-go@v1.12.0/internal/internal_event_handlers.go:833 +0x3fd\ngithub.com/spiral/sdk-go/internal.(*workflowExecutionContextImpl).ProcessWorkflowTask(0xc0009288c0, 0xc000116ed0)\n\tgithub.com/spiral/sdk-go@v1.12.0/internal/internal_task_handlers.go:874 +0xca8\ngithub.com/spiral/sdk-go/internal.(*workflowTaskHandlerImpl).ProcessWorkflowTask(0xc0001e4a50, 0xc000116ed0, 0xc0009dee70)\n\tgithub.com/spiral/sdk-go@v1.12.0/internal/internal_task_handlers.go:723 +0x493\ngithub.com/spiral/sdk-go/internal.(*workflowTaskPoller).processWorkflowTask(0xc0000b45b0, 0xc000116ed0)\n\tgithub.com/spiral/sdk-go@v1.12.0/internal/internal_task_pollers.go:284 +0x2cd\ngithub.com/spiral/sdk-go/internal.(*workflowTaskPoller).ProcessTask(0xc0000b45b0, {0x1594180, 0xc000116ed0})\n\tgithub.com/spiral/sdk-go@v1.12.0/internal/internal_task_pollers.go:255 +0x6c\ngithub.com/spiral/sdk-go/internal.(*baseWorker).processTask(0xc000200400, {0x1593d40, 0xc000122250})\n\tgithub.com/spiral/sdk-go@v1.12.0/internal/internal_worker_base.go:362 +0x167\ncreated by github.com/spiral/sdk-go/internal.(*baseWorker).runTaskDispatcher\n\tgithub.com/spiral/sdk-go@v1.12.0/internal/internal_worker_base.go:282 +0xba"}
2022-05-12T06:15:35.243Z WARN temporal Failed to process workflow task. {"Namespace": "default", "TaskQueue": "default", "WorkerID": "default:4fe939cb-4f79-47c6-a1e9-8b6dad29ef7f", "WorkflowType": "DummyWorkflow", "WorkflowID": "XXX", "RunID": "5a1bfd24-70e9-4cef-863e-5a2f0377223c", "Attempt": 1, "Error": "unknown command CommandType: Timer, ID: 5, possible causes are nondeterministic workflow definition code or incompatible change in the workflow definition"}
2022-05-12T06:15:35.243Z DEBUG temporal sequenceID {"before": 3}
2022-05-12T06:15:35.243Z DEBUG temporal sequenceID {"after": 4}
2022-05-12T06:15:35.243Z DEBUG temporal outgoing message {"data": "\nE\u0008\u0004\u0012\u000fDestroyWorkflow\u001a0{\"runId\":\"5a1bfd24-70e9-4cef-863e-5a2f0377223c\"} {\"taskQueue\":\"default\",\"tickTime\":\"2022-05-12T06:14:46Z\",\"replay\":true}"}
2022-05-12T06:15:35.244Z DEBUG temporal received message {"data": "\n\u001f\u0008\u0004*\u001b\n\u0019\n\u0017\n\u0008encoding\u0012\u000bbinary/null"}
2022-05-12T06:15:35.254Z DEBUG temporal workflow execute {"runID": "5a1bfd24-70e9-4cef-863e-5a2f0377223c", "workflow info": {"WorkflowExecution":{"ID":"XXX","RunID":"5a1bfd24-70e9-4cef-863e-5a2f0377223c"},"WorkflowType":{"Name":"DummyWorkflow"},"TaskQueueName":"default","WorkflowExecutionTimeout":0,"WorkflowRunTimeout":0,"WorkflowTaskTimeout":10000000000,"Namespace":"default","Attempt":1,"WorkflowStartTime":"2022-05-12T06:14:46.868631545Z","CronSchedule":"","ContinuedExecutionRunID":"","ParentWorkflowNamespace":"","ParentWorkflowExecution":null,"Memo":null,"SearchAttributes":{},"BinaryChecksum":"366aad4717fdb22d55eebef7c454528a"}}
2022-05-12T06:15:35.254Z DEBUG temporal sequenceID {"before": 4}
2022-05-12T06:15:35.254Z DEBUG temporal sequenceID {"after": 5}
2022-05-12T06:15:35.254Z DEBUG temporal workflow task started {"time": "1s"}
2022-05-12T06:15:35.254Z DEBUG temporal outgoing message {"data": "\n\ufffd\u0006\u0008\u0005\u0012\rStartWorkflow\u001a\ufffd\u0005{\"info\":{\"WorkflowExecution\":{\"ID\":\"XXX\",\"RunID\":\"5a1bfd24-70e9-4cef-863e-5a2f0377223c\"},\"WorkflowType\":{\"Name\":\"DummyWorkflow\"},\"TaskQueueName\":\"default\",\"WorkflowExecutionTimeout\":0,\"WorkflowRunTimeout\":0,\"WorkflowTaskTimeout\":10000000000,\"Namespace\":\"default\",\"Attempt\":1,\"WorkflowStartTime\":\"2022-05-12T06:14:46.868631545Z\",\"CronSchedule\":\"\",\"ContinuedExecutionRunID\":\"\",\"ParentWorkflowNamespace\":\"\",\"ParentWorkflowExecution\":null,\"Memo\":null,\"SearchAttributes\":{\"indexed_fields\":{\"SkyTeacherId\":{\"metadata\":{\"encoding\":\"anNvbi9wbGFpbg==\",\"type\":\"SW50\"},\"data\":\"MTY1MjI=\"}}},\"BinaryChecksum\":\"366aad4717fdb22d55eebef7c454528a\"}}*D\n\u001f\n\u0016\n\u0008encoding\u0012\njson/plain\u0012\u000516522\n!\n\u0016\n\u0008encoding\u0012\njson/plain\u0012\u00072592000 {\"taskQueue\":\"default\",\"tickTime\":\"2022-05-12T06:14:46Z\",\"replay\":true}"}
2022-05-12T06:15:35.255Z DEBUG temporal received message {"data": "\n\"\u0008\ufffdF\u0012\u0008NewTimer\u001a\u0011{\"ms\":2592000000}*\u0000\n\u001f\u0008\u0005*\u001b\n\u0019\n\u0017\n\u0008encoding\u0012\u000bbinary/null"}
2022-05-12T06:15:35.255Z DEBUG temporal sequenceID {"before": 5}
2022-05-12T06:15:35.255Z DEBUG temporal sequenceID {"after": 6}
2022-05-12T06:15:35.255Z DEBUG temporal workflow task started {"time": "1s"}
2022-05-12T06:15:35.255Z DEBUG temporal outgoing message {"data": "\nY\u0008\u0006\u0012\u000cInvokeSignal\u001aG{\"runId\":\"5a1bfd24-70e9-4cef-863e-5a2f0377223c\",\"name\":\"cancelRemoval\"} {\"taskQueue\":\"default\",\"tickTime\":\"2022-05-12T06:15:35Z\"}"}
2022-05-12T06:15:35.257Z DEBUG temporal received message {"data": "\n\u001f\u0008\u0006*\u001b\n\u0019\n\u0017\n\u0008encoding\u0012\u000bbinary/null\nB\u0008\ufffdF\u0012\u0010CompleteWorkflow\u001a\u0002{}*'\n%\n\u0016\n\u0008encoding\u0012\njson/plain\u0012\u000b\"CANCELLED\""}
2022-05-12T06:15:35.257Z DEBUG temporal sequenceID {"before": 6}
2022-05-12T06:15:35.257Z DEBUG temporal sequenceID {"after": 7}
2022-05-12T06:15:35.257Z DEBUG temporal outgoing message {"data": "\nE\u0008\u0007\u0012\u000fDestroyWorkflow\u001a0{\"runId\":\"5a1bfd24-70e9-4cef-863e-5a2f0377223c\"} {\"taskQueue\":\"default\",\"tickTime\":\"2022-05-12T06:15:35Z\",\"replay\":true}"}
2022-05-12T06:15:35.257Z DEBUG temporal received message {"data": "\n\u001f\u0008\u0007*\u001b\n\u0019\n\u0017\n\u0008encoding\u0012\u000bbinary/null"}
Environment/Versions
- Temporal Version: 1.13.0, SDK version 1.1.1