artisan queue:work timeouts however artisan queue:listen process job

[rrolla]

• Laravel Version: 5.7.21
• PHP Version: 7.1.23
• Database Driver & Version: sqlanywhere 17.0.0
• OS: Ubuntu 18.04, Debian 9

Output of: $pdo = \DB::connection('sasql_001')->getPdo();

PDOConnection {#1213
  inTransaction: false
  attributes: {
    CASE: NATURAL
    ERRMODE: EXCEPTION
    PERSISTENT: false
    DRIVER_NAME: "sqlanywhere"
    ORACLE_NULLS: NATURAL
    CLIENT_VERSION: "17.0.0."
    SERVER_VERSION: "17.0.9.4838"
    STATEMENT_CLASS: array:2 [
      0 => "Doctrine\DBAL\Driver\PDOStatement"
      1 => []
    ]
    DEFAULT_FETCH_MODE: BOTH
  }
}

Description:

I made a connection where laravel connects to sqlanywhere database using https://github.com/josueneo/laravel5-sqlanywhere package.

In config/database.php connections array i add:

'sasql_001' => [
    'driver' => 'sqlanywhere',
    'dsn' => 'sqlanywhere:',
    'username' => env('SA_USERNAME', 'root'),
    'password' => env('SA_PASSWORD', 'yourpassword'),
    'database' => env('SA_DB_NAME_001', 'sqladb'),
    'databasefile' => env('SA_DB_FILE_001', ''),
    'host' => env('SA_HOST', 'localhost'),
    'port' => env('SA_PORT', '2638'),
    'options' => 'ASTOP=no;CharSet=utf8',
],

For example when i go to uri /delayed app do some queries in sqlanywhere model and return data. Then i make Queueable Job to get the same data from model and if there is some data send email.

For development i make get uri /dispatch to execute:

Route::get('dispatch', function () {
    dispatch(new App\Jobs\RemindMaintenance())
        ->onConnection('maintenance')
        ->onQueue('maintenance');
});

In .env file i change

CACHE_DRIVER=redis
SESSION_DRIVER=redis
QUEUE_CONNECTION=redis
BROADCAST_DRIVER=redis

In config/queue.php connections array i add

'maintenance' => [
    'driver' => 'redis',
    'connection' => 'default',
    'queue' => 'maintenance',
    'retry_after' => 14400,
],

Steps To Reproduce:

I start: php artisan queue:listen maintenance --tries=1 --queue=maintenance --timeout=30

And hit http://myapp.test/dispatch

I see in terminal that job is processed (everything works like should work)

[2019-01-20 23:31:12][107] Processing: App\Jobs\RemindMaintenance
[2019-01-20 23:35:07][107] Processed: App\Jobs\RemindMaintenance

Then i stop queue:listen and start php artisan queue:work maintenance --tries=1 --queue=maintenance --timeout=30

Hit one more time http://myapp.test/dispatch

And in terminal see that job is processing and failed

[2019-01-20 23:37:04][109] Processing: App\Jobs\RemindMaintenance
[2019-01-20 24:05:08][109] Failed: App\Jobs\RemindMaintenance

And whatever i set as job --timeout 30 sec or 12400 sec at the end it always timeouts

Illuminate\Queue\MaxAttemptsExceededException: App\Jobs\RemindMaintenance has been attempted too many times or run too long. The job may have previously timed out. in /var/www/vendor/laravel/framework/src/Illuminate/Queue/Worker.php:401

Strange is that, if I call only one simple query in the model, then queue:work ... finish succesfully Job.

[2019-01-20 23:54:12][111] Processing: App\Jobs\RemindMaintenance
[2019-01-20 23:55:47][111] Processed: App\Jobs\RemindMaintenance

Thanks for your help.

[laurencei]

What does the error log say for the failed job?

[sisve]

What operating system are you using? Windows does not support the things needed for proper timeouts.

[rrolla]

What operating system are you using? Windows does not support the things needed for proper timeouts.

I try on two OS: Ubuntu 18.04 and Debian 9

[laurencei]

@rrolla - what is in the laravel error logs?

Because it has Failed: App\Jobs\RemindMaintenance - so it should have something in the logs as to what failed?

[rrolla]

@rrolla - what is in the laravel error logs?

Because it has Failed: App\Jobs\RemindMaintenance - so it should have something in the logs as to what failed?

I will post logs today.

[rrolla]

Thats the problem that i cannot get anything useful from stacktrace:

[2019-01-21 22:16:14] rolla.ERROR: App\Jobs\RemindMaintenance has been attempted too many times or run too long. The job may have previously timed out. {"exception":"[object] (Illuminate\\Queue\\MaxAttemptsExceededException(code: 0): App\\Jobs\\RemindMaintenance has been attempted too many times or run too long. The job may have previously timed out. at /myapp/vendor/laravel/framework/src/Illuminate/Queue/Worker.php:396)
[stacktrace]
#0 /myapp/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(316): Illuminate\\Queue\\Worker->markJobAsFailedIfAlreadyExceedsMaxAttempts('redis', Object(Illuminate\\Queue\\Jobs\\RedisJob), 3)
#1 /myapp/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(272): Illuminate\\Queue\\Worker->process('redis', Object(Illuminate\\Queue\\Jobs\\RedisJob), Object(Illuminate\\Queue\\WorkerOptions))
#2 /myapp/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(118): Illuminate\\Queue\\Worker->runJob(Object(Illuminate\\Queue\\Jobs\\RedisJob), 'redis', Object(Illuminate\\Queue\\WorkerOptions))
#3 /myapp/vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php(101): Illuminate\\Queue\\Worker->daemon('redis', 'maintenance', Object(Illuminate\\Queue\\WorkerOptions))
#4 /myapp/vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php(85): Illuminate\\Queue\\Console\\WorkCommand->runWorker('redis', 'maintenance')
#5 [internal function]: Illuminate\\Queue\\Console\\WorkCommand->handle()
#6 /myapp/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(29): call_user_func_array(Array, Array)
#7 /myapp/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(87): Illuminate\\Container\\BoundMethod::Illuminate\\Container\\{closure}()
#8 /myapp/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(31): Illuminate\\Container\\BoundMethod::callBoundMethod(Object(Illuminate\\Foundation\\Application), Array, Object(Closure))
#9 /myapp/vendor/laravel/framework/src/Illuminate/Container/Container.php(564): Illuminate\\Container\\BoundMethod::call(Object(Illuminate\\Foundation\\Application), Array, Array, NULL)
#10 /myapp/vendor/laravel/framework/src/Illuminate/Console/Command.php(184): Illuminate\\Container\\Container->call(Array)
#11 /myapp/vendor/symfony/console/Command/Command.php(251): Illuminate\\Console\\Command->execute(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Illuminate\\Console\\OutputStyle))
#12 /myapp/vendor/laravel/framework/src/Illuminate/Console/Command.php(171): Symfony\\Component\\Console\\Command\\Command->run(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Illuminate\\Console\\OutputStyle))
#13 /myapp/vendor/symfony/console/Application.php(886): Illuminate\\Console\\Command->run(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput))
#14 /myapp/vendor/symfony/console/Application.php(262): Symfony\\Component\\Console\\Application->doRunCommand(Object(Laravel\\Horizon\\Console\\WorkCommand), Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput))
#15 /myapp/vendor/symfony/console/Application.php(145): Symfony\\Component\\Console\\Application->doRun(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput))
#16 /myapp/vendor/laravel/framework/src/Illuminate/Console/Application.php(89): Symfony\\Component\\Console\\Application->run(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput))
#17 /myapp/vendor/laravel/framework/src/Illuminate/Foundation/Console/Kernel.php(122): Illuminate\\Console\\Application->run(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput))
#18 /myapp/artisan(37): Illuminate\\Foundation\\Console\\Kernel->handle(Object(Symfony\\Component\\Console\\Input\\ArgvInput), Object(Symfony\\Component\\Console\\Output\\ConsoleOutput))
#19 {main}
"}

[sisve]

[2019-01-20 23:37:04][109] Processing: App\Jobs\RemindMaintenance
[2019-01-20 24:05:08][109] Failed: App\Jobs\RemindMaintenance

Is this a verbatim log output? The time 2019-01-20 24:05:08 looks weird to me, I'm used to seeing 2019-01-21 00:05:08 in 24h format.

You describe a scenario where you do queue:listen, kill it, and restart it, and see a log output about a failed job afterwards. This matches a scenario where queue:listen was executing a job when you killed it, and the second queue:listen would find that job after your $retry_after setting, and see that it has been tried too many times. There's nothing in the log output that proves that it's the same job that is both started and failed. It could be to different jobs, which makes sense when you realize you are running with $retry_after=4 hours. This could mean that the job that failed at 24:05:08 was started at 20:05:08-ish, and isn't the same as the one started at 23:37:04.

You've only given us the log entry that states that a job failed. Are there any other log entries that indicate why a job failed? Perhaps other exceptions reported?

Strange is that, if I call only one simple query in the model, then queue:work ... finish succesfully Job.

This indicate that there is something in your job that is crashing. It isn't about queue:work vs queue:listen, it is entirely about what your job is doing.

Clear out the log files and start over the testing. Give us the entire output of the log files and the source code of the job. We're currently lacking enough information to debug this and is basically guessing at the moment.

[rrolla]

I start from zero

Add Logs to Job __construct and handle method

Job class:

<?php

namespace App\Jobs;

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

class RemindMaintenance implements ShouldQueue
{
    use Dispatchable, InteractsWithQueue, Queueable, SerializesModels;

    /**
     * The number of seconds the job can run before timing out.
     *
     * @var int
     */
    public $timeout = 7200; // 2 hours

    /**
     * Create a new job instance.
     *
     * @return void
     */
    public function __construct()
    {
        \Log::info('App\Jobs\RemindMaintenance __construct');
    }

    /**
     * Execute the job.
     *
     * @return void
     */
    public function handle()
    {
        \Log::info('App\Jobs\RemindMaintenance handle');

        \Log::info(\App\Monitor\DbVer::first());

        \Log::info(\App\Monitor\TorderHuvud::first());
    }

}

DbVer model:

<?php

namespace App\Monitor;

use Illuminate\Database\Eloquent\Model;

class DbVer extends Model {

    protected $connection = 'sasql_001';
    protected $table = 'monitor.DB_VER';

    public $timestamps = false;

}

TorderHuvud model:

<?php

namespace App\Monitor;

use Illuminate\Database\Eloquent\Model;

class TorderHuvud extends Model {

    protected $connection = 'sasql_001';
    protected $table = 'monitor.TORDER_HUVUD';

    protected $primaryKey = 'toh_id';

    public $timestamps = false;

}

Execute command: php artisan queue:work maintenance --tries=1 --queue=maintenance --timeout=7200 --memory=512

Hit: http://myapp.test/dispatch

terminal output:

[2019-01-30 13:14:36][170] Processing: App\Jobs\RemindMaintenance
Killed

log output:

[2019-01-30 13:14:33] rolla.INFO: App\Jobs\RemindMaintenance __construct  
[2019-01-30 13:14:36] rolla.INFO: App\Jobs\RemindMaintenance handle  

But no exceptions throw.

Also: dmesg | grep php nothing outputs

[sisve]

So, to be clear, the problem in your last comment isn't about queue:work vs queue:listen, but that there are no logging output for DbVer::first() and TorderHuvud::first()?

It's unclear from the provided code what's happening. I would blame database transactions or something that blocks you from querying the data. Anyhow, there's nothing obvious about the queue system what I can see. You could try a simple DB::select('SELECT 1'); which shouldn't be affected by transactions, locks or anything else.

I have never used SQL Anywhere and cannot tell you how to check for locks or transactions interfering with your query.

[rrolla]

Totally the same code

Execute command: php artisan queue:listen maintenance --tries=1 --queue=maintenance --timeout=7200 --memory=512

terminal output:

[2019-01-31 10:13:15][185] Processing: App\Jobs\RemindMaintenance
[2019-01-31 10:13:17][185] Processed:  App\Jobs\RemindMaintenance

log output:

[2019-01-31 10:13:17] rolla.INFO: {"db_version":"09.00.10.092"}  
[2019-01-31 10:13:17] rolla.INFO: {"toh_id":57,"art_id":973,"toh_ordernr":"3567","toh_userid":"ADMIN","toh_tn_nr":1278,"tp_projekt":null,"toh_datum_reg":"2014-02-20 12:00:07.691","toh_datum_start":"2014-02-20 00:00:00.000","toh_datum_slut":"2014-03-21 00:00:00.000","toh_arbets_timmar":176,"toh_kundkod_villkor":"27501","toh_typ":1,"toh_rappnr_sista":0,"toh_datum_hist":"2014-03-22 21:29:19.266","toh_antal":"1.000000","toh_status":1,"toh_prioritet":9,"toh_datum_villkor":null,"toh_stalle":1,"toh_locked":0,"toh_datum_slut0":"2014-03-21 00:00:00.000","toh_artnr":"P3567 GISAB FILT","toh_ko_nr":"S000012","toh_andrad_av":null,"toh_andrad_nar":null,"toh_variantkod":null,"toh_kompr":null,"toh_till_snittpris":null,"kfg_nr":null,"toh_forsening_konstaterad":null,"toh_exporterad":0,"toh_dellangder_andrad_index":null,"toh_orsakande_id":117,"toh_orsakande_typ":7,"toh_exporterad_fifo":1}  

[driesvints]

I didn't realize this before but SQL Anywhere is unfortunately not a database type we support. Please try to test this with one of the supported database types and report back if the issue persists: https://laravel.com/docs/6.x/database#introduction

[axtricssolutions]

I am facing an exactly same situation. I am running a Job using queue:work --tries=3 --timeout --delay=3 and it is failing with Illuminate\Queue\Worker->maxAttemptsExceededException().

I am sure that code within Job is correct but there are no logs to find out why it is failing.

Please also note that i am using this job to sync products from Magento and i am doing this in batches. I pull 100 products at a time and run another job after 5 secs. But the syncing always fails at random number.