Bug? Webhooks can't be executed after image deployment

問題
1

Describe the problem/error/question

Hello. Everything works fine, but if I need to change a variable or dockerfile and I need to re-deploy the image then after the deployment and everything is “up” any webhook trigger is “reachable” to the URL.

What is the error message (if any)?

{
    "code": 404,
    "message": "The requested webhook \"POST 06630a86-63f6-4c7d-80eb-36a25fb91333\" is not registered.",
    "hint": "The workflow must be active for a production URL to run successfully. You can activate the workflow using the toggle in the top-right of the editor. Note that unlike test URL calls, production URL calls aren't shown on the canvas (only in the executions list)"
}

So I have to turn off all the toggles for each workflow that contains a webhook trigger and reactivate them using the toggle:

image
image1236×486 25.6 KB

And then the webhook triggers are accessible again.

I’m worried if my instance crashes at some point where I am not available and after the auto-rebuild, any of the webhooks will work.

Information on your n8n setup

  • n8n version: 1.9.3
  • Database (default: SQLite): Postgresql + redis
  • n8n EXECUTIONS_PROCESS setting (default: own, main): queue
  • Running n8n via (Docker, npm, n8n cloud, desktop app): railway + docker
  • Operating system: linux
3

Hi @yukyo, I am very sorry you’re having trouble.

@a1ekseev reported a similar issue recently where problems with one trigger during the n8n startup can prevent other workflows from activating as expected (even though the UI would show them as active).

Can you check your server logs if the workflows for which the webhook endpoint returns a 404 status appear after the Start Active Workflows line? Depending on your log level you should see logs like below for each of your workflows:

forum-topic-31335-mqtt-n8n-1  | 2023-10-10T14:05:00.733Z | info     |  ================================ "{ file: 'ActiveWorkflowRunner.js', function: 'init' }"
forum-topic-31335-mqtt-n8n-1  | 2023-10-10T14:05:00.734Z | info     |    Start Active Workflows: "{ file: 'ActiveWorkflowRunner.js', function: 'init' }"
forum-topic-31335-mqtt-n8n-1  | 2023-10-10T14:05:00.734Z | info     |  ================================ "{ file: 'ActiveWorkflowRunner.js', function: 'init' }"
forum-topic-31335-mqtt-n8n-1  | 2023-10-10T14:05:00.734Z | info     |    - WF 1 (ID: BDzt2QNkILqOMfT2) "{ file: 'ActiveWorkflowRunner.js', function: 'init' }"
forum-topic-31335-mqtt-n8n-1  | 2023-10-10T14:05:00.734Z | debug    | Initializing active workflow "WF 1" (startup) "{\n  workflowName: 'WF 1',\n  workflowId: 'BDzt2QNkILqOMfT2',\n  file: 'ActiveWorkflowRunner.js',\n  function: 'init'\n}"
forum-topic-31335-mqtt-n8n-1  | 2023-10-10T14:05:00.788Z | verbose  | Successfully started workflow "WF 1" "{\n  workflowName: 'WF 1',\n  workflowId: 'BDzt2QNkILqOMfT2',\n  file: 'ActiveWorkflowRunner.js',\n  function: 'init'\n}"

If you can’t see these lines for all of your workflows can you check the last workflow with a Initializing active workflow log line for any errors?

5

Hi @MutedJam, I have created a test n8n project to show where the issue is. This is exactly what is happening in my main instance.

Please see this 5 min video where I explain how to reproduce the issue: wooden-lunchroom _ Railway - 17 October 2023 (the link expires in 48 hours, let me know if you need me to re-upload it).

Main deployment log:

2023-10-17T17:23:47.261Z | debug | License init complete "{ file: 'start.js', function: 'init' }"

2023-10-17T17:23:47.265Z | debug | Binary data service init complete "{ file: 'start.js', function: 'init' }"

2023-10-17T17:23:47.266Z | debug | External hooks init complete "{ file: 'start.js', function: 'init' }"

2023-10-17T17:23:47.269Z | debug | External secrets init complete "{ file: 'start.js', function: 'init' }"

2023-10-17T17:23:48.150Z | debug | Wait tracker querying database for waiting executions "{ file: 'WaitTracker.js', function: 'getWaitingExecutions' }"

2023-10-17T17:23:49.290Z | debug | Initialising Redis client of type client(bull) connection with host: containers-us-west-72.railway.app and port: 6821 "{ file: 'RedisServiceHelper.js', function: 'getRedisStandardClient' }"

2023-10-17T17:23:49.292Z | debug | Initialising Redis client of type subscriber(bull) connection with host: containers-us-west-72.railway.app and port: 6821 "{ file: 'RedisServiceHelper.js', function: 'getRedisStandardClient' }"

2023-10-17T17:23:49.512Z | debug | No key pair files found, generating new pair using type: ed25519 "{\n file: 'sourceControlPreferences.service.ee.js',\n function: 'setPreferences'\n}"

2023-10-17T17:23:49.592Z | debug | Initializing event bus... "{ file: 'MessageEventBus.js', function: 'initialize' }"

2023-10-17T17:23:49.596Z | debug | Initializing event writer "{ file: 'MessageEventBus.js', function: 'initialize' }"

2023-10-17T17:23:49.603Z | debug | Checking for unsent event messages "{ file: 'MessageEventBus.js', function: 'initialize' }"

2023-10-17T17:23:49.604Z | debug | Start logging into /home/node/.n8n/n8nEventLog.log "{ file: 'MessageEventBus.js', function: 'initialize' }"

2023-10-17T17:23:49.604Z | debug | MessageEventBus initialized "{ file: 'MessageEventBus.js', function: 'initialize' }"

Version: 1.9.3

2023-10-17T17:23:49.606Z | debug | Server ID: main-3368V2xdiky5Ed8s "{ file: 'Server.js', function: 'start' }"

2023-10-17T17:23:49.644Z [Rudder] debug: in flush

2023-10-17T17:23:49.644Z [Rudder] debug: batch size is 1

2023-10-17T17:23:49.648Z [Rudder] debug: no existing flush timer, creating new one

2023-10-17T17:23:49.847Z | info | ================================ "{ file: 'ActiveWorkflowRunner.js', function: 'init' }"

2023-10-17T17:23:49.847Z | info | Start Active Workflows: "{ file: 'ActiveWorkflowRunner.js', function: 'init' }"

2023-10-17T17:23:49.847Z | info | ================================ "{ file: 'ActiveWorkflowRunner.js', function: 'init' }"

2023-10-17T17:23:49.847Z | info | - Webhook 1 (ID: H7ZjPCOW5KG6AbHY) "{ file: 'ActiveWorkflowRunner.js', function: 'init' }"

2023-10-17T17:23:49.848Z | debug | Initializing active workflow "Webhook 1" (startup) "{\n workflowName: 'Webhook 1',\n workflowId: 'H7ZjPCOW5KG6AbHY',\n file: 'ActiveWorkflowRunner.js',\n function: 'init'\n}"

2023-10-17T17:23:49.954Z | verbose | Successfully started workflow "Webhook 1" "{\n workflowName: 'Webhook 1',\n workflowId: 'H7ZjPCOW5KG6AbHY',\n file: 'ActiveWorkflowRunner.js',\n function: 'init'\n}"

2023-10-17T17:23:49.954Z | info | => Started "{ file: 'ActiveWorkflowRunner.js', function: 'init' }"

2023-10-17T17:23:49.954Z | info | - Cron 1 (ID: ENbhnkacIHcy42Qs) "{ file: 'ActiveWorkflowRunner.js', function: 'init' }"

2023-10-17T17:23:49.954Z | debug | Initializing active workflow "Cron 1" (startup) "{\n workflowName: 'Cron 1',\n workflowId: 'ENbhnkacIHcy42Qs',\n file: 'ActiveWorkflowRunner.js',\n function: 'init'\n}"

2023-10-17T17:23:49.963Z | verbose | Successfully activated workflow "Cron 1" "{\n workflowId: 'ENbhnkacIHcy42Qs',\n workflowName: 'Cron 1',\n file: 'ActiveWorkflowRunner.js',\n function: 'add'\n}"

2023-10-17T17:23:49.967Z | verbose | Successfully started workflow "Cron 1" "{\n workflowName: 'Cron 1',\n workflowId: 'ENbhnkacIHcy42Qs',\n file: 'ActiveWorkflowRunner.js',\n function: 'init'\n}"

2023-10-17T17:23:49.967Z | info | => Started "{ file: 'ActiveWorkflowRunner.js', function: 'init' }"

2023-10-17T17:23:49.967Z | verbose | Finished initializing active workflows (startup) "{ file: 'ActiveWorkflowRunner.js', function: 'init' }"

Editor is now accessible via:

http://localhost:5678/

2023-10-17T17:24:09.648Z [Rudder] debug: in flush

2023-10-17T17:24:09.649Z [Rudder] debug: cancelling existing timer...

2023-10-17T17:24:09.649Z [Rudder] debug: cancelling existing flushTimer...

2023-10-17T17:24:09.649Z [Rudder] debug: batch size is 1

2023-10-17T17:24:29.838Z [Rudder] debug: in flush

2023-10-17T17:24:29.839Z [Rudder] debug: cancelling existing timer...

2023-10-17T17:24:29.839Z [Rudder] debug: queue is empty, nothing to flush

2023-10-17T17:24:48.150Z | debug | Wait tracker querying database for waiting executions "{ file: 'WaitTracker.js', function: 'getWaitingExecutions' }"

2023-10-17T17:24:49.975Z | debug | Received trigger for workflow "Cron 1" "{ file: 'ActiveWorkflowRunner.js', function: 'returnFunctions.emit' }"

Log after re-deployment triggering webhook from postman when it wasn’t working and then deactivated, and reactivated, and then worked:

2023-10-17T17:48:10.481Z [Rudder] debug: in flush

2023-10-17T17:48:10.481Z [Rudder] debug: cancelling existing flushTimer...

2023-10-17T17:48:10.481Z [Rudder] debug: batch size is 2

2023-10-17T17:48:10.661Z | debug | Received trigger for workflow "Cron 1" "{ file: 'ActiveWorkflowRunner.js', function: 'returnFunctions.emit' }"

Started with job ID: 30 (Execution ID: 30)

2023-10-17T17:48:15.734Z | debug | Skipping execution data for execution 30 since there are no PostExecutionPromise. "{ file: 'WorkflowRunner.js' }"

2023-10-17T17:48:24.162Z | debug | Received webhook "POST" for path "c113e417-fe01-432e-afd4-d1081d02d263" "{ file: 'ActiveWorkflowRunner.js', function: 'executeWebhook' }"

2023-10-17T17:48:30.853Z [Rudder] debug: in flush

2023-10-17T17:48:30.853Z [Rudder] debug: cancelling existing timer...

2023-10-17T17:48:30.853Z [Rudder] debug: queue is empty, nothing to flush

2023-10-17T17:48:50.638Z | debug | Received webhook "POST" for path "c113e417-fe01-432e-afd4-d1081d02d263" "{ file: 'ActiveWorkflowRunner.js', function: 'executeWebhook' }"

2023-10-17T17:48:51.519Z | debug | Received webhook "POST" for path "c113e417-fe01-432e-afd4-d1081d02d263" "{ file: 'ActiveWorkflowRunner.js', function: 'executeWebhook' }"

2023-10-17T17:48:52.335Z | debug | Received webhook "POST" for path "c113e417-fe01-432e-afd4-d1081d02d263" "{ file: 'ActiveWorkflowRunner.js', function: 'executeWebhook' }"

2023-10-17T17:49:03.888Z | debug | Received webhook "POST" for path "c113e417-fe01-432e-afd4-d1081d02d263" "{ file: 'ActiveWorkflowRunner.js', function: 'executeWebhook' }"

2023-10-17T17:49:08.342Z | debug | Wait tracker querying database for waiting executions "{ file: 'WaitTracker.js', function: 'getWaitingExecutions' }"

2023-10-17T17:49:09.081Z | debug | Received webhook "POST" for path "c113e417-fe01-432e-afd4-d1081d02d263" "{ file: 'ActiveWorkflowRunner.js', function: 'executeWebhook' }"

2023-10-17T17:49:10.653Z | debug | Received trigger for workflow "Cron 1" "{ file: 'ActiveWorkflowRunner.js', function: 'returnFunctions.emit' }"

Started with job ID: 31 (Execution ID: 31)

2023-10-17T17:49:15.693Z | debug | Skipping execution data for execution 31 since there are no PostExecutionPromise. "{ file: 'WorkflowRunner.js' }"

2023-10-17T17:49:31.979Z | verbose | Updating versionId for workflow H7ZjPCOW5KG6AbHY for user a6359be7-ef2b-4df0-95dc-0d5d1a43f20d after saving "{\n previousVersionId: '9f441ba9-c1ca-49d8-b824-01517010e3e1',\n newVersionId: '0a190b24-f499-4bf4-83f5-54a68ca98e9f',\n file: 'workflows.services.js',\n function: 'update'\n}"

2023-10-17T17:49:32.020Z [Rudder] debug: no existing flush timer, creating new one

2023-10-17T17:49:36.319Z | verbose | Updating versionId for workflow H7ZjPCOW5KG6AbHY for user a6359be7-ef2b-4df0-95dc-0d5d1a43f20d after saving "{\n previousVersionId: '0a190b24-f499-4bf4-83f5-54a68ca98e9f',\n newVersionId: '7558623a-cdff-4120-aaf3-ecdd6c18a8d5',\n file: 'workflows.services.js',\n function: 'update'\n}"

2023-10-17T17:49:41.799Z | debug | Received webhook "POST" for path "c113e417-fe01-432e-afd4-d1081d02d263" "{ file: 'ActiveWorkflowRunner.js', function: 'executeWebhook' }"

Started with job ID: 32 (Execution ID: 32)

2023-10-17T17:49:41.863Z | verbose | Started execution of workflow "Webhook 1" from webhook with execution ID 32 "{\n executionId: '32',\n file: 'WebhookHelpers.js',\n function: 'executeWebhook'\n}"

2023-10-17T17:49:46.886Z | debug | Skipping execution data for execution 32 since there are no PostExecutionPromise. "{ file: 'WorkflowRunner.js' }"

2023-10-17T17:49:52.020Z [Rudder] debug: batch size is 2

Dockerfile:

FROM n8nio/n8n:latest

ARG PGPASSWORD
ARG PGHOST
ARG PGPORT
ARG PGDATABASE
ARG PGUSER
ARG ENCRYPTION_KEY

ENV DB_TYPE=postgresdb
ENV DB_POSTGRESDB_DATABASE=$PGDATABASE
ENV DB_POSTGRESDB_HOST=$PGHOST
ENV DB_POSTGRESDB_PORT=$PGPORT
ENV DB_POSTGRESDB_USER=$PGUSER
ENV DB_POSTGRESDB_PASSWORD=$PGPASSWORD
ENV N8N_ENCRYPTION_KEY=$ENCRYPTION_KEY

CMD ["n8n" "start"]

Hope it helps,
Thanks.

6

Hi @yukyo, I am afraid I am not a railway user and as such not familiar with the specifics of this platform. Is this also happening for you when running n8n outside of railway, for example using a simple docker compose setup like below?

docker-compose.yml 
services:
  postgres:
    image: postgres:15
    restart: unless-stopped
    environment:
      - POSTGRES_USER=n8n
      - POSTGRES_PASSWORD=n8n
      - POSTGRES_DB=n8n
    volumes:
      - ./db_data:/var/lib/postgresql/data
    ports:
      - 5432:5432
    healthcheck:
      test: ['CMD-SHELL', 'pg_isready -h localhost -U n8n -d n8n']
      interval: 5s
      timeout: 5s
      retries: 10
  redis:
    image: redis:6-alpine
    restart: unless-stopped
    healthcheck:
      test: ['CMD', 'redis-cli', 'ping']
      interval: 5s
      timeout: 5s
      retries: 10
  n8n_main:
    image: n8nio/n8n:1.9.3
    restart: unless-stopped
    environment:
      - DB_TYPE=postgresdb
      - DB_POSTGRESDB_HOST=postgres
      - DB_POSTGRESDB_PORT=5432
      - DB_POSTGRESDB_DATABASE=n8n
      - DB_POSTGRESDB_USER=n8n
      - DB_POSTGRESDB_PASSWORD=n8n
      - QUEUE_HEALTH_CHECK_ACTIVE=true
      - N8N_DIAGNOSTICS_ENABLED=false
      - QUEUE_BULL_REDIS_HOST=redis
      - EXECUTIONS_MODE=queue
      - N8N_LOG_LEVEL=debug
    ports:
      - 5678:5678
    volumes:
      - ./n8n_data:/home/node/.n8n
    depends_on:
      postgres:
        condition: service_healthy
      redis:
        condition: service_healthy
  n8n_worker:
    image: n8nio/n8n:1.9.3
    restart: unless-stopped
    environment:
      - DB_TYPE=postgresdb
      - DB_POSTGRESDB_HOST=postgres
      - DB_POSTGRESDB_PORT=5432
      - DB_POSTGRESDB_DATABASE=n8n
      - DB_POSTGRESDB_USER=n8n
      - DB_POSTGRESDB_PASSWORD=n8n
      - QUEUE_HEALTH_CHECK_ACTIVE=true
      - N8N_DIAGNOSTICS_ENABLED=false
      - QUEUE_BULL_REDIS_HOST=redis
      - EXECUTIONS_MODE=queue
      - N8N_LOG_LEVEL=debug
    command: worker
    volumes:
      - ./n8n_data:/home/node/.n8n
    depends_on:
      postgres:
        condition: service_healthy
      redis:
        condition: service_healthy
      n8n_main:
        condition: service_started
7

@MutedJam I’ll try later deploying a normal container hosted on a vm without railway, but I don’t see how that could cause an issue. Do the logs look normal? Isn’t there anything weird?

Example:
when cron was initializing:

2023-10-17T17:23:49.954Z | info | - Cron 1 (ID: ENbhnkacIHcy42Qs) "{ file: 'ActiveWorkflowRunner.js', function: 'init' }"

2023-10-17T17:23:49.954Z | debug | Initializing active workflow "Cron 1" (startup) "{\n workflowName: 'Cron 1',\n workflowId: 'ENbhnkacIHcy42Qs',\n file: 'ActiveWorkflowRunner.js',\n function: 'init'\n}"

2023-10-17T17:23:49.963Z | verbose | Successfully activated workflow "Cron 1" "{\n workflowId: 'ENbhnkacIHcy42Qs',\n workflowName: 'Cron 1',\n file: 'ActiveWorkflowRunner.js',\n function: 'add'\n}"

2023-10-17T17:23:49.967Z | verbose | Successfully started workflow "Cron 1" "{\n workflowName: 'Cron 1',\n workflowId: 'ENbhnkacIHcy42Qs',\n file: 'ActiveWorkflowRunner.js',\n function: 'init'\n}"

2023-10-17T17:23:49.967Z | info | => Started "{ file: 'ActiveWorkflowRunner.js', function: 'init' }"

I can see two successfully messages there. One activated one started.

But for the webhook I only see one:

2023-10-17T17:23:49.847Z | info | - Webhook 1 (ID: H7ZjPCOW5KG6AbHY) "{ file: 'ActiveWorkflowRunner.js', function: 'init' }"

2023-10-17T17:23:49.848Z | debug | Initializing active workflow "Webhook 1" (startup) "{\n workflowName: 'Webhook 1',\n workflowId: 'H7ZjPCOW5KG6AbHY',\n file: 'ActiveWorkflowRunner.js',\n function: 'init'\n}"

2023-10-17T17:23:49.954Z | verbose | Successfully started workflow "Webhook 1" "{\n workflowName: 'Webhook 1',\n workflowId: 'H7ZjPCOW5KG6AbHY',\n file: 'ActiveWorkflowRunner.js',\n function: 'init'\n}"

2023-10-17T17:23:49.954Z | info | => Started "{ file: 'ActiveWorkflowRunner.js', function: 'init' }"

The started one, but not the activated. So something is not “activating” the webhook.

8

In the meanwhile, I managed to resolve the issue with this scenario :rofl:

image
image1497×362 38.4 KB

What seems interesting if I don’t add the 30-sec wait at the beginning when the actions start running, then it fails… maybe the instance is still running processes? Also, what I found is that if I don’t use split in batches and I try to run all the actions at once never works. Even if the result of the execution is successfully, it doesn’t seem to update the statuses.

9

Hi @yukyo, while I am glad to hear you found a workaround this shouldn’t be necessary in the first place. The logs you have shared seem fine, the webhook workflow will only read Initializing active workflow and Successfully started workflow during the startup.

The active status of a workflow shown in the UI is based on the records in your database. These are also the workflows each n8n instance activates during startup, seemingly successful based on the logs you have shared. So I am wondering how requests are routed on your end. Is there a chance railway only routes requests to your re-deployed containers once they pass a health check (and is using an older container no longer responding to your requests as expected until then)?

It’d be great if you could try the above docker compose example with your exact test workflows once you have the chance. This can also be done locally and would help verify if this behaviour is related to your current environment or not.

If this is also happening for you locally using this example setup, can you share the exact workflows you have used for testing?