SignalWithStartWorkflow not triggering

hazcod · September 7, 2020, 9:54am

Hi, I have an issue where SignalWithStartWorkflow is not triggering the workflow.

Caller:

	logger.Debug("signaling investigateDomain")
	if _, err := w.Client.SignalWithStartWorkflow(ctx, investigateOpts.ID, "input", investInput, investigateOpts, w.InvestigateDomainWorkflow); err != nil {
		logger.WithError(err).Error("could not signal to new workflow to store domain")
	}
	logger.WithField("enum_domain", "domain").Info("finished StoreDomainWorkflow")

And the workflow in question:

func (w *Workflows) InvestigateDomainWorkflow(ctx workflow.Context) (err error) {
	var signalVal InvestigateDomainInput

	selector := workflow.NewSelector(ctx)
	selector.AddReceive(workflow.GetSignalChannel(ctx, "input"), func(c workflow.ReceiveChannel, more bool) {
		c.Receive(ctx, &signalVal)

		info := workflow.GetInfo(ctx)
		logger := w.Logger.WithFields(logrus.Fields{
			"domain": signalVal.Domain.Name, "owner_id": signalVal.Domain.OwnerId, "attempt": info.Attempt,
			"workflow": info.WorkflowExecution.ID, "job_id": signalVal.Job.Id, "type": "InvestigateDoman",
		})
		logger.Info("executing")

And the logs mentioning no error or workflow run:

worker_1      | time="2020-09-07T09:45:46Z" level=debug msg="signaling investigateDomain" activity=6 attempt=1 domain=xxx owner_id=2 workflow=d800f1ed-830a-4e97-a39a-4a3bb32166fc
worker_1      | time="2020-09-07T09:45:46Z" level=info msg="finished StoreDomainWorkflow" activity=6 attempt=1 domain=xxx enum_domain=domain owner_id=2 workflow=d800f1ed-830a-4e97-a39a-4a3bb32166fc

The worker has called workflow.RegisterWorkflow(investigateDomainWorkflow).

maxim · September 7, 2020, 11:52pm

Did you call selector.Select?

hazcod · September 8, 2020, 5:27am

Hi @maxim, yes, the workflow looks like this:

func (w *Workflows) InvestigateDomainWorkflow(ctx workflow.Context) (err error) {
	var signalVal InvestigateDomainInput

	selector := workflow.NewSelector(ctx)
	selector.AddReceive(workflow.GetSignalChannel(ctx, "input"), func(c workflow.ReceiveChannel, more bool) {
		c.Receive(ctx, &signalVal)

		info := workflow.GetInfo(ctx)
		logger := w.Logger.WithFields(logrus.Fields{
			"domain": signalVal.Domain.Name, "owner_id": signalVal.Domain.OwnerId, "attempt": info.Attempt,
			"workflow": info.WorkflowExecution.ID, "job_id": signalVal.Job.Id, "type": "InvestigateDoman",
		})
		logger.Info("executing")

		// ....

		logger.Debug("finished")
	})
	selector.Select(ctx)
	return nil
}

maxim · September 8, 2020, 2:34pm

Could you attach the workflow execution history for this workflow? Also, the log you posted says that workflow has finished. Looking at the code it is not possible without Select unblocking and processing the signal.

hazcod · September 8, 2020, 3:24pm

Hi @maxim, I mean w.Client.SignalWithStartWorkflow finished with err nil but no trace of the workflow executing.

docker exec -ti 5cdf5225b5cf tctl --namespace micro-domain --ad temporal:7233 workflow list
2020/09/08 15:23:49 INFO  No logger configured for temporal client. Created default one.
         WORKFLOW TYPE         |                  WORKFLOW ID                   |                RUN ID                | TASK QUEUE | START TIME | EXECUTION TIME | END TIME  
  InvestigateDomainWorkflow    | InvestigateDomainWorkflow-2-588206402172354561 | dcf2464e-e37b-40de-9340-1c576cdc4aca |            | 14:52:28   | 15:47:00       | 15:22:28  
  InvestigateDomainWorkflow    | InvestigateDomainWorkflow-2-588206277449482241 | 7c8c1583-9231-48ec-8b7f-180849afeca9 |            | 14:51:50   | 15:46:00       | 15:21:50  
  InvestigateDomainWorkflow    | InvestigateDomainWorkflow-2-588206227604733953 | 973e2367-8c73-4add-900a-4f2d1441afcd |            | 14:51:35   | 15:46:00       | 15:21:35  
  InvestigateDomainWorkflow    | InvestigateDomainWorkflow-2-588206036648361985 | 36aa8016-4939-44df-af87-1c45ec5c0584 |            | 14:51:13   | 15:46:00       | 15:21:13  
  LightEnumerateDomainWorkflow | LightEnumerateDomain-2-588206036648361985      | f72cf8cb-72ff-4b74-832f-f3caf32e5f7b |            | 14:50:36   | 14:45:00       | 15:10:36  
  StoreDomainWorkflow          | 495b6e12-470e-480f-8e8f-29dcc8e86342           | a58f851f-52ca-4125-888b-1e1ac5688560 |            | 14:52:28   | 14:52:28       | 14:52:28  
  StoreDomainWorkflow          | bdb785d9-6e8c-4ba2-acf7-c6e039170f96           | 13cc7633-1022-40db-b80b-6b1897442d75 |            | 14:51:50   | 14:51:50       | 14:51:50  
  StoreDomainWorkflow          | 6cbea372-f4f2-4d75-8253-7f2695b22fdd           | ff47c19a-16aa-444d-a4b4-6ded4406f45b |            | 14:51:34   | 14:51:34       | 14:51:35  
  StoreDomainWorkflow          | bc14e103-cac9-487b-8f1f-be275d26f524           | de01e1f5-b0a5-4c84-aaa4-302576ce2fbb |            | 14:51:12   | 14:51:12       | 14:51:14

maxim · September 8, 2020, 6:23pm

What is the output of the list command with “-op” flag?

hazcod · September 8, 2020, 6:30pm

@maxim:

% docker exec -ti micro-domain_temporal_1 tctl --namespace micro-domain --ad temporal:7233 wf list -op
2020/09/08 18:30:03 INFO  No logger configured for temporal client. Created default one.
         WORKFLOW TYPE         |                  WORKFLOW ID                   |                RUN ID                | TASK QUEUE | START TIME | EXECUTION TIME  
  InvestigateDomainWorkflow    | InvestigateDomainWorkflow-2-588249177223397377 | ab32e32f-5982-4dcb-99b1-83e1c030b0b3 |            | 18:30:02   | 19:25:00        
  InvestigateDomainWorkflow    | InvestigateDomainWorkflow-2-588248979486310401 | 3530bf23-e2df-4031-941f-12667df5fea9 |            | 18:29:01   | 19:24:00        
  InvestigateDomainWorkflow    | InvestigateDomainWorkflow-2-588248769736900609 | 3a13ec14-fa34-49a9-8db4-45996cf4799a |            | 18:28:45   | 19:23:00        
  LightEnumerateDomainWorkflow | LightEnumerateDomain-2-588248769736900609      | 58d5acc6-cd78-445f-81a3-e65fc923d142 |            | 18:27:57   | 18:22:00        
  DeepEnumerateDomainWorkflow  | DeepEnumerateDomain-2-588248769736900609       | 1e519371-1718-4c55-abb0-8bcc4cd40a0b |            | 18:27:57   | 18:22:00

maxim · September 8, 2020, 6:32pm

So I see many InvestigateDomainWorkflow instances both open and closed. Why do you think there is no trace of the workflow executing?

hazcod · September 8, 2020, 6:35pm

Hmm, odd, I see no logs whatsoever.
How do you see they are open/closed?

maxim · September 8, 2020, 6:36pm

% docker exec -ti micro-domain_temporal_1 tctl --namespace micro-domain --ad temporal:7233 wf list -op
2020/09/08 18:30:03 INFO  No logger configured for temporal client. Created default one.
         WORKFLOW TYPE         |                  WORKFLOW ID                   |                RUN ID                | TASK QUEUE | START TIME | EXECUTION TIME  
  InvestigateDomainWorkflow    | InvestigateDomainWorkflow-2-588249177223397377 | ab32e32f-5982-4dcb-99b1-83e1c030b0b3 |            | 18:30:02   | 19:25:00        
  InvestigateDomainWorkflow    | InvestigateDomainWorkflow-2-588248979486310401 | 3530bf23-e2df-4031-941f-12667df5fea9 |            | 18:29:01   | 19:24:00        
  InvestigateDomainWorkflow    | InvestigateDomainWorkflow-2-588248769736900609 | 3a13ec14-fa34-49a9-8db4-45996cf4799a |            | 18:28:45   | 19:23:00        
  LightEnumerateDomainWorkflow | LightEnumerateDomain-2-588248769736900609      | 58d5acc6-cd78-445f-81a3-e65fc923d142 |            | 18:27:57   | 18:22:00        
  DeepEnumerateDomainWorkflow  | DeepEnumerateDomain-2-588248769736900609       | 1e519371-1718-4c55-abb0-8bcc4cd40a0b |            | 18:27:57   | 18:22:00

Shows 3 open instances of the InvestigateDomainWorkflow workflow

hazcod · September 8, 2020, 7:28pm

After converting all invocations of LocalActivity to Activity it now magically works.

hazcod · September 9, 2020, 8:01am

@maxim: seems the issue is not solved:
Not sure why, but my Workflow stays at WorkflowExecutionSignaled again.

  1  WorkflowExecutionStarted   {WorkflowType:{Name:InvestigateDomainWorkflow},               
                                 ParentInitiatedEventId:0, TaskQueue:{Name:DomainEnumeration,  
                                 Kind:Normal}, Input:[], WorkflowExecutionTimeout:30m0s,       
                                 WorkflowRunTimeout:30m0s, WorkflowTaskTimeout:10s,            
                                 Initiator:Workflow, LastCompletionResult:[],                  
                                 OriginalExecutionRunId:c7fa3341-cb7d-4917-9666-ced29e2042d3,  
                                 Identity:1@1ec9b57dc799@,                                     
                                 FirstExecutionRunId:c7fa3341-cb7d-4917-9666-ced29e2042d3,     
                                 RetryPolicy:{InitialInterval:30s, BackoffCoefficient:1,       
                                 MaximumInterval:50m0s, MaximumAttempts:5,                     
                                 NonRetryableErrorTypes:[len=0]}, Attempt:1,                   
                                 WorkflowExecutionExpirationTime:2020-09-09                    
                                 07:19:02.564 +0000 UTC, CronSchedule:44 * * * *,              
                                 FirstWorkflowTaskBackoff:54m58s, Header:{Fields:map{}}}       
  2  WorkflowExecutionSignaled  {SignalName:input, Input:[{Domain:map[blacklist:[]            
                                 blacklist_ports:[] id:5.883944715745034e+17                   
                                 name:www.ironpeak.be owner_id:2                               
                                 top_domain:5.88393759006294e+17 whitelist:[]]                 
                                 Job:map[DomainId:5.883944715745034e+17                        
                                 Id:5.883944716024873e+17 Schedule:44 *                        
                                 * * * TimeCreated:0001-01-01T00:00:00Z                        
                                 Type:InvestigateDomainWorkflow                                
                                 Workflow:InvestigateDomainWorkflow-2-588394471574503425]}],   
                                 Identity:1@1ec9b57dc799@}

My main workflow which calls this one through activities already finished with unhandled signals.
Hm, now it started running after 18 minutes of silence.
The stack is empty.
And my first activity is never called it seems & eventually it ends with WorkflowExecutionTimedOut (RetryState:Timeout)

hazcod · September 9, 2020, 8:18am

Something odd, since my logs mentioning the start of the workflow executing via the Signal, temporal does not:

Logs:

time="2020-09-09T08:18:10Z" level=info msg="executing investigateDOmainWorkflow"

time="2020-09-09T08:18:10Z" level=info msg=executing attempt=1 domain=status.ironpeak.be job_id=588409999785459713 owner_id=2 type=InvestigateDomain workflow=InvestigateDomainWorkflow-2-588409999639937025

Temporal:

% docker exec -ti micro-domain_temporal_1 tctl --namespace micro-domain --ad temporal:7233 wf show -w InvestigateDomainWorkflow-2-588409999639937025 
2020/09/09 08:18:05 INFO  No logger configured for temporal client. Created default one.
  1  WorkflowExecutionStarted   {WorkflowType:{Name:InvestigateDomainWorkflow},               
                                 ParentInitiatedEventId:0, TaskQueue:{Name:DomainEnumeration,  
                                 Kind:Normal}, Input:[], WorkflowExecutionTimeout:30m0s,       
                                 WorkflowRunTimeout:30m0s, WorkflowTaskTimeout:10s,            
                                 Initiator:Workflow, LastCompletionResult:[],                  
                                 OriginalExecutionRunId:b2da91f2-f01e-4905-b258-3dced71827d9,  
                                 Identity:1@c11a17d97927@,                                     
                                 FirstExecutionRunId:b2da91f2-f01e-4905-b258-3dced71827d9,     
                                 RetryPolicy:{InitialInterval:30s, BackoffCoefficient:1,       
                                 MaximumInterval:50m0s, MaximumAttempts:5,                     
                                 NonRetryableErrorTypes:[len=0]}, Attempt:1,                   
                                 WorkflowExecutionExpirationTime:2020-09-09                    
                                 08:38:01.442 +0000 UTC, CronSchedule:3 * * * *,               
                                 FirstWorkflowTaskBackoff:54m59s, Header:{Fields:map{}}}       
  2  WorkflowExecutionSignaled  {SignalName:input, Input:[{Domain:map[blacklist:[]            
                                 blacklist_ports:[] id:5.88409999639937e+17                    
                                 name:status.ironpeak.be owner_id:2                            
                                 top_domain:5.884095487623496e+17 whitelist:[]]                
                                 Job:map[DomainId:5.88409999639937e+17                         
                                 Id:5.884099997854597e+17 Schedule:3 *                         
                                 * * * TimeCreated:0001-01-01T00:00:00Z                        
                                 Type:InvestigateDomainWorkflow                                
                                 Workflow:InvestigateDomainWorkflow-2-588409999639937025]}],   
                                 Identity:1@c11a17d97927@}                                     
niels@django micro-domain % docker exec -ti micro-domain_temporal_1 tctl --namespace micro-domain --ad temporal:7233 wf stack -w InvestigateDomainWorkflow-2-588409999639937025
Query result:
[]

maxim · September 9, 2020, 2:12pm

This workflow is started with a cron expression. So workflow is expected to not execute until the first execution time comes. Look at WorkflowExecutionStarted.FirstWorkflowTaskBackoff. It determines the execution delay which is 55 minutes in this case.

hazcod · September 9, 2020, 2:30pm

But wouldnt the empty signal trigger it to execute?

maxim · September 9, 2020, 2:31pm

I believe signal is not forcing the immediate execution.

hazcod · September 9, 2020, 2:37pm

Hm. Any workaround to trigger a cron workflow immediately?

maxim · September 9, 2020, 2:42pm

Start it twice with different IDs. One time with cron another without.

Topic		Replies	Views
How to Unit Test a Workflow that Starts via SignalWithStartWorkflow()? Community Support go-sdk	3	160	January 26, 2024
Signal not working in unit test Community Support signals	3	479	December 4, 2022
SignalWithStart as childworkflow Community Support java-sdk	1	247	July 29, 2023
SignalWithStartWorkflow - racy with this pattern? Community Support go-sdk	3	157	January 8, 2024
SignalWithStartWorkflow + Cron: Expected Behaviour? Community Support go-sdk	2	428	January 12, 2023

SignalWithStartWorkflow not triggering

Related Topics