DEADLINE_EXCEEDED

[beliven-daniele-sarnari]

Hello,

we are using this library with a cloud run laravel instance.
For some reasons CloudTasks is reading a deadline of 60s, even if the Job timeout is set to 300s.

Task content:

{
  "uuid": "a06da189-83dd-4366-b3ab-cedc1fd7ba22",
  "displayName": "App\\Jobs\\TestJob",
  "job": "Illuminate\\Queue\\CallQueuedHandler@call",
  "maxTries": null,
  "maxExceptions": null,
  "failOnTimeout": false,
  "backoff": null,
  "timeout": 300,
  "retryUntil": null,
  "data": {
    "commandName": "App\\Jobs\\TestJob",
    "command": "O:16:\"App\\Jobs\\TestJob\":1:{s:4:\"\u0000*\u0000n\";i:20;}"
  },
  "telescope_uuid": "9b75e5de-bd34-4869-89a5-da98d7df4fa1",
  "internal": {
    "attempts": 0
  }
}

CloudTask logs error:

{
  "insertId": "1thj77cc3yy",
  "jsonPayload": {
    "@type": "type.googleapis.com/google.cloud.tasks.logging.v1.TaskActivityLog",
    "attemptResponseLog": {
      "attemptDuration": "60.027352s",
      "dispatchCount": "3",
      "maxAttempts": 0,
      "responseCount": "0",
      "retryTime": "2024-03-01T15:58:03.376746Z",
      "scheduleTime": "2024-03-01T15:57:01.149385Z",
      "status": "DEADLINE_EXCEEDED",
      "targetAddress": "POST https://crun-europe-west1-6nag4uco6a-ew.a.run.app/handle-task",
      "targetType": "HTTP"
    },
    "task": "projects/pj-cloud-run-debug/locations/europe-west1/queues/ctqu-europe-west1/tasks/App-Jobs-TestJob-6232a47d-a86d-4a5e-a144-74acd5803a33-1709308500725"
  },
  "logName": "projects/pj-cloud-run-debug/logs/cloudtasks.googleapis.com%2Ftask_operations_log",
  "receiveTimestamp": "2024-03-01T15:58:03.457366806Z",
  "resource": {
    2
  },
  "severity": "ERROR",
  "timestamp": "2024-03-01T15:58:02.976792965Z",
}

TestJob:

<?php

namespace App\Jobs;

use Illuminate\Bus\Queueable;
use Illuminate\Contracts\Queue\ShouldQueue;
use Illuminate\Foundation\Bus\Dispatchable;
use Illuminate\Queue\InteractsWithQueue;
use Illuminate\Queue\SerializesModels;

class TestJob implements ShouldQueue
{
    use Dispatchable;
    use InteractsWithQueue;
    use Queueable;
    use SerializesModels;

    public int $timeout = 300;

    protected $n;

    /**
     * Create a new job instance.
     *
     * @return void
     */
    public function __construct($n)
    {
        $this->n = $n;
    }

    /**
     * Execute the job.
     *
     * @return void
     */
    public function handle()
    {
        $result = $this->fibonacci($this->n);
        info("Fibonacci result for {$this->n} is {$result}");

        sleep(60);

        info("Job finished after waiting for 2 minutes.");
    }

    /**
     * Calcola il numero di Fibonacci.
     *
     * @param int $n
     * @return int
     */
    protected function fibonacci($n)
    {
        if ($n <= 1) {
            return $n;
        }

        return $this->fibonacci($n - 1) + $this->fibonacci($n - 2);
    }
}

queue.php

'cloudtasks' => [
            'driver' => 'cloudtasks',
            'project' => env('STACKKIT_CLOUD_TASKS_PROJECT', ''),
            'location' => env('STACKKIT_CLOUD_TASKS_LOCATION', ''),
            'handler' => env('STACKKIT_CLOUD_TASKS_HANDLER', ''),
            'queue' => env('STACKKIT_CLOUD_TASKS_QUEUE', 'default'),
            'service_account_email' => env('STACKKIT_CLOUD_TASKS_SERVICE_EMAIL', ''),
            'signed_audience' => env('STACKKIT_CLOUD_TASKS_SIGNED_AUDIENCE', true),
            // Optional: The deadline in seconds for requests sent to the worker. If the worker
            // does not respond by this deadline then the request is cancelled and the attempt
            // is marked as a DEADLINE_EXCEEDED failure.
            'dispatch_deadline' => null,
            'backoff' => 0,
        ],

Thanks for the support

[beliven-daniele-sarnari]

Tried also setting dispatch_deadline to 300, no changes

[beliven-daniele-sarnari]

@marickvantuil do you have any idea why?

laravel-google-cloud-tasks-queue/src/CloudTasksQueue.php

Line 191 in f64a3a2

$task->setDispatchDeadline(new Duration(['seconds' => $this->config['dispatch_deadline']]));

seems right to me

Log of new created job, duration is not passed

[marickvantuil]

I can't reproduce it!

A few things:

1. The $timeout property on a job currently doesn't do anything in this package. Will hopefully make it work in v4.

2. I've tested the dispatch_deadline and it seems to be working for me. A few observations:

In the queue log it also won't show me the dispatchDeadline on the TaskActivityLog, like your screenshot. However, when the job finally fails, I do see a attemptDuration which matches my setting:

Queue configuration

TaskActivityLog

Perhaps the container request timeout setting is still on 60s?

[beliven-daniele-sarnari]

@marickvantuil
I checked everything...can't figure out what's the root cause...

Look at this one:

How is that even possible? The cloud run Request timeout is set to 300 seconds, but the log shows that the request was terminated after 60 seconds, citing the cloud run request timeout as the reason.

[schaeferalex]

How is that even possible? The cloud run Request timeout is set to 300 seconds, but the log shows that the request was terminated after 60 seconds, citing the cloud run request timeout as the reason.

Do you set a max_execution_time time by any chance in a php.ini/cloudrun.ini?

[beliven-daniele-sarnari]

How is that even possible? The cloud run Request timeout is set to 300 seconds, but the log shows that the request was terminated after 60 seconds, citing the cloud run request timeout as the reason.

Do you set a max_execution_time time by any chance in a php.ini/cloudrun.ini?

Yes, that's my Dockerfile:

FROM serversideup/php:beta-8.2-fpm-nginx-alpine

ENV S6_CMD_WAIT_FOR_SERVICES=1
ENV AUTORUN_ENABLED false
ENV AUTORUN_LARAVEL_STORAGE_LINK true
ENV PHP_FPM_PM_CONTROL ondemand
ENV PHP_FPM_PM_MAX_CHILDREN 100
ENV PHP_MAX_EXECUTION_TIME 300
ENV LOG_OUTPUT_LEVEL debug

RUN docker-php-ext-install bcmath

# Install Cloud SQL Proxy
RUN curl -o /usr/sbin/cloud-sql-proxy https://storage.googleapis.com/cloud-sql-connectors/cloud-sql-proxy/v2.7.1/cloud-sql-proxy.linux.amd64
RUN chmod +x /usr/sbin/cloud-sql-proxy

# Copy startup.sh in entrypoints directory
COPY --chmod=755 ./deployment/build/entrypoint.d/ /etc/entrypoint.d/
RUN pwd
RUN docker-php-serversideup-s6-init

# Copy website data
COPY backend/ /var/www/html

# Fix permissions
RUN chown -R nginx:nginx /var/www/html

I've already been in touch with the docker image creator here link and it doesn't seem an issue on the container side (also because i tried another image here without solving the problem).

[beliven-daniele-sarnari]

[marickvantuil]

I've got a Cloud Run container running too with a similar image (serversideup/php:8.2-fpm-nginx-v2.2.1) and can reproduce the issue. After debugging, and checking with a regular request that is not from Cloud Tasks, I noticed nginx times out after 60 seconds. In Cloud Tasks this does appear as DEADLINE_EXCEEDED. Changing the nginx timeout settings to something longer than the dispatch deadline fixes the problem for me.

I'm not too much of an nginx expert so maybe just one of these config options suffices, but I've set these:

Config options

proxy_connect_timeout 180s;
proxy_read_timeout 180s;
fastcgi_read_timeout 180s;

Now my Cloud Run container runs longer than 60s but exits after 65s (which is the dispatch_deadline from the queue.php config):

Screenshot

Perhaps the same applies to your setup?

[schaeferalex]

I've got a Cloud Run container running too with a similar image (serversideup/php:8.2-fpm-nginx-v2.2.1) and can reproduce the issue.

I believe it is because the serversideup/php image runs a reverse proxy which has a default timeout of 60s: https://serversideup.net/open-source/docker-php/docs/guide/using-s6-overlay

[beliven-daniele-sarnari]

I've got a Cloud Run container running too with a similar image (serversideup/php:8.2-fpm-nginx-v2.2.1) and can reproduce the issue. After debugging, and checking with a regular request that is not from Cloud Tasks, I noticed nginx times out after 60 seconds. In Cloud Tasks this does appear as DEADLINE_EXCEEDED. Changing the nginx timeout settings to something longer than the dispatch deadline fixes the problem for me.

I'm not too much of an nginx expert so maybe just one of these config options suffices, but I've set these:

Config options
Now my Cloud Run container runs longer than 60s but exits after 65s (which is the dispatch_deadline from the queue.php config):

Screenshot
Perhaps the same applies to your setup?

This was the solution.
Incredible how there is no log that references to nginx proxy timeout.
Thanks everyone for the support!