Queue Mode, Two Worker, One ExecutionId, but multiple real Executions

Describe the problem/error/question

We updated n8n from 1.5.1 to 1.42.1. Seems like something changed on the queue mode handling.
We have two worker and it seems like both of them doing the same execution. It feels flaky and we could not reproduce this in our dev system yet. In the n8n ui we can only see one execution, but our customer got 5-6 mails for each execution (was a send mail workflow).

ExecutonId 6451834 :: See the Start job: in the Logs.

Worker 1

 ~ ▓▒░ k -n n8n logs n8n-workflow-engine-worker-77d9957db5-8qpgw | grep "6451834"                                                                                                      ░▒▓ ✔  n8n-prod/n8n ○ 
2024-06-06T14:57:39.921Z | info     | Start job: 6179209 (Workflow ID: 170 | Execution: 6451834) "{ file: 'worker.js', function: 'runJob' }"
2024-06-06T14:57:55.126Z | debug    | Queued worker execution status for 6451834 is "waiting" "{ file: 'worker.js', function: 'additionalData.setExecutionStatus' }"
2024-06-06T14:57:55.127Z | debug    | Executing hook (hookFunctionsSaveWorker) "{\n  executionId: '6451834',\n  workflowId: '170',\n  file: 'WorkflowExecuteAdditionalData.js',\n  function: 'workflowExecuteAfter'\n}"
2024-06-06T14:57:55.127Z | debug    | Save execution data to database for execution ID 6451834 "{\n  executionId: '6451834',\n  workflowId: '170',\n  finished: false,\n  stoppedAt: 2024-06-06T14:57:55.127Z,\n  file: 'sharedHookFunctions.js',\n  function: 'updateExistingExecution'\n}"
2024-06-06T15:00:24.391Z | debug    | Wait tracker found 1 executions. Setting timer for IDs: 6451834 "{ file: 'WaitTracker.js', function: 'getWaitingExecutions' }"
2024-06-06T15:00:55.128Z | debug    | Wait tracker resuming execution 6451834 "{\n  executionId: '6451834',\n  file: 'WaitTracker.js',\n  function: 'startExecution'\n}"
2024-06-06T15:00:55.150Z | info     | Started with job ID: 6179235 (Execution ID: 6451834) "{ file: 'WorkflowRunner.js', function: 'enqueueExecution' }"
2024-06-06T15:00:55.163Z | info     | Start job: 6179235 (Workflow ID: 170 | Execution: 6451834) "{ file: 'worker.js', function: 'runJob' }"
2024-06-06T15:00:55.187Z | info     | Start job: 6179237 (Workflow ID: 170 | Execution: 6451834) "{ file: 'worker.js', function: 'runJob' }"
2024-06-06T15:00:55.765Z | debug    | Executing hook (hookFunctionsSaveWorker) "{\n  executionId: '6451834',\n  workflowId: '170',\n  file: 'WorkflowExecuteAdditionalData.js',\n  function: 'workflowExecuteAfter'\n}"
2024-06-06T15:00:55.766Z | debug    | Save execution data to database for execution ID 6451834 "{\n  executionId: '6451834',\n  workflowId: '170',\n  finished: true,\n  stoppedAt: 2024-06-06T15:00:55.765Z,\n  file: 'sharedHookFunctions.js',\n  function: 'updateExistingExecution'\n}"
2024-06-06T15:00:55.894Z | debug    | Executing hook (hookFunctionsSaveWorker) "{\n  executionId: '6451834',\n  workflowId: '170',\n  file: 'WorkflowExecuteAdditionalData.js',\n  function: 'workflowExecuteAfter'\n}"
2024-06-06T15:00:55.950Z | debug    | Save execution data to database for execution ID 6451834 "{\n  executionId: '6451834',\n  workflowId: '170',\n  finished: true,\n  stoppedAt: 2024-06-06T15:00:55.894Z,\n  file: 'sharedHookFunctions.js',\n  function: 'updateExistingExecution'\n}"
2024-06-06T15:00:55.963Z | debug    | Reading execution data for execution 6451834 from db for PostExecutionPromise. "{ file: 'WorkflowRunner.js' }"

Worker 2

 ~ ▓▒░ k -n n8n logs n8n-workflow-engine-worker-77d9957db5-srwvq | grep "6451834"                                                                                                      ░▒▓ ✔  n8n-prod/n8n ○ 
2024-06-06T15:00:01.604Z | debug    | Wait tracker found 1 executions. Setting timer for IDs: 6451834 "{ file: 'WaitTracker.js', function: 'getWaitingExecutions' }"
2024-06-06T15:00:55.127Z | debug    | Wait tracker resuming execution 6451834 "{\n  executionId: '6451834',\n  file: 'WaitTracker.js',\n  function: 'startExecution'\n}"
2024-06-06T15:00:55.150Z | info     | Started with job ID: 6179236 (Execution ID: 6451834) "{ file: 'WorkflowRunner.js', function: 'enqueueExecution' }"
2024-06-06T15:00:55.159Z | info     | Start job: 6179234 (Workflow ID: 170 | Execution: 6451834) "{ file: 'worker.js', function: 'runJob' }"
2024-06-06T15:00:55.162Z | info     | Start job: 6179236 (Workflow ID: 170 | Execution: 6451834) "{ file: 'worker.js', function: 'runJob' }"
2024-06-06T15:00:55.165Z | info     | Start job: 6179238 (Workflow ID: 170 | Execution: 6451834) "{ file: 'worker.js', function: 'runJob' }"
2024-06-06T15:00:55.617Z | debug    | Executing hook (hookFunctionsSaveWorker) "{\n  executionId: '6451834',\n  workflowId: '170',\n  file: 'WorkflowExecuteAdditionalData.js',\n  function: 'workflowExecuteAfter'\n}"
2024-06-06T15:00:55.617Z | debug    | Save execution data to database for execution ID 6451834 "{\n  executionId: '6451834',\n  workflowId: '170',\n  finished: true,\n  stoppedAt: 2024-06-06T15:00:55.617Z,\n  file: 'sharedHookFunctions.js',\n  function: 'updateExistingExecution'\n}"
2024-06-06T15:00:55.626Z | debug    | Reading execution data for execution 6451834 from db for PostExecutionPromise. "{ file: 'WorkflowRunner.js' }"
2024-06-06T15:00:55.651Z | debug    | Executing hook (hookFunctionsSaveWorker) "{\n  executionId: '6451834',\n  workflowId: '170',\n  file: 'WorkflowExecuteAdditionalData.js',\n  function: 'workflowExecuteAfter'\n}"
2024-06-06T15:00:55.651Z | debug    | Save execution data to database for execution ID 6451834 "{\n  executionId: '6451834',\n  workflowId: '170',\n  finished: true,\n  stoppedAt: 2024-06-06T15:00:55.651Z,\n  file: 'sharedHookFunctions.js',\n  function: 'updateExistingExecution'\n}"
2024-06-06T15:00:55.780Z | debug    | Executing hook (hookFunctionsSaveWorker) "{\n  executionId: '6451834',\n  workflowId: '170',\n  file: 'WorkflowExecuteAdditionalData.js',\n  function: 'workflowExecuteAfter'\n}"
2024-06-06T15:00:55.780Z | debug    | Save execution data to database for execution ID 6451834 "{\n  executionId: '6451834',\n  workflowId: '170',\n  finished: true,\n  stoppedAt: 2024-06-06T15:00:55.780Z,\n  file: 'sharedHookFunctions.js',\n  function: 'updateExistingExecution'\n}"

It feels strange that there are so many Start job: logs with the same execution.

I saw that there is another report which may solved the bug, but 1.43 hat the big db structure change.

Do you have any idea what could be the cause? Anyone had the same issues?

Information on your n8n setup

  • n8n version:: 1.42.1
  • Database (default: SQLite): postgresql
  • n8n EXECUTIONS_PROCESS setting (default: own, main): main
  • n8n EXECUTIONS_MODE: queue
  • Running n8n via (Docker, npm, n8n cloud, desktop app): k8s docker
  • Operating system: linux

I see, fix(core): Start WaitTracker only in the main container by netroy · Pull Request #9600 · n8n-io/n8n · GitHub may be the Issue. I try to reproduce in our dev system

Yes, Issue is reproducable with wait nodes and workflow imports via cli.

( n8n import:workflow --separate --input=./assets/processes/ )

Due to 1.43.0 has so many db changes, a release with the bugfix as 1.42.2 would be really nice. Or at least warn users about version 1.42.1 with wait nodes and queue mode.

Hey @rfehling-mittwald,

That is some nice digging there, I have asked internally if we plan to release some older versions with the fix in it. I suspect we may do a release for latest but we may not go pre 1.43 with it.

Ok, we will try next week an update to > 1.45.0 or the smaller releases above 1.43

Seems like only large amount of waiting (> 2 min [when node is in WAITING mode and not in RUNNING mode]) makes the error occure.

1 Like

Hey @rfehling-mittwald,

Good news, We are currently working on a 1.42.2 release which should be available later today.

Wow, that’s really great news. Thank you very much!!

This topic was automatically closed 7 days after the last reply. New replies are no longer allowed.