Skip to content

[Bug] Issues with sticky execution/queries/signals #170

Closed
@mzavatsky

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)

  1. Start workflow
  2. Reload workers with rr reset
  3. 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"}
  1. 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):
image

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)

  1. Start workflow
  2. Restart roadrunner server with docker restart roadrunner_container
  3. 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\"}"}
  1. 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.

  1. Try to query again and get expected answer
  2. Try to send signal7.

Web UI:
Signal is processed correctly, but after an error:
image

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

Metadata

Labels

BugSomething isn't working

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions