search

spatie / mailcoach-support

Questions and support for Mailcoach
https://mailcoach.app
31 stars 2 forks source link

SendCampaignJob fails #253

Closed electronick86 closed 4 years ago

electronick86 commented 4 years ago

Hello Guys,

A I mentionned here #248 , I had some trouble a few days ago with a SendCampaignJob that runs multiple times.

I don't have the problem anymore as I create unique index on the mailcoach_sends table for (subscriber_id+campaign_id) and that the job SendCampaignJob don't attempt several time ( public int $tries = 1; )

The project concerned by this issue have two mailing list (217k + 130k subscribers).

The problem is that everytime I send a campaign, I see that the SendCampaignJob fails... even if the campaign seems to be send without any issue.

Horizon_-_Failed_Jobs

I have sent two campaigns today, the problem occurs twice.

Campaign ID 117 created at 06h45 Campaign ID 118 created at 08h30

The errors appears every time about ~11 minutes later.

[2020-10-01 06:56:06] production.ERROR: Spatie\Mailcoach\Jobs\SendCampaignJob has been attempted too many times or run too long. The job may have previously timed out. {"exception":"[object] (Illuminate\\Queue\\MaxAttemptsExceededException(code: 0): Spatie\\Mailcoach\\Jobs\\SendCampaignJob has been attempted too many times or run too long. The job may have previously timed out. at /var/www/html/vendor/laravel/framework/src/Illuminate/Queue/Worker.php:648)
[stacktrace]
#0 /var/www/html/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(436): Illuminate\\Queue\\Worker->maxAttemptsExceededException()
#1 /var/www/html/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(346): Illuminate\\Queue\\Worker->markJobAsFailedIfAlreadyExceedsMaxAttempts()
#2 /var/www/html/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(306): Illuminate\\Queue\\Worker->process()
#3 /var/www/html/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(132): Illuminate\\Queue\\Worker->runJob()
#4 /var/www/html/vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php(112): Illuminate\\Queue\\Worker->daemon()
#5 /var/www/html/vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php(96): Illuminate\\Queue\\Console\\WorkCommand->runWorker()
#6 /var/www/html/vendor/laravel/horizon/src/Console/WorkCommand.php(46): Illuminate\\Queue\\Console\\WorkCommand->handle()
#7 [internal function]: Laravel\\Horizon\\Console\\WorkCommand->handle()
#8 /var/www/html/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(37): call_user_func_array()
#9 /var/www/html/vendor/laravel/framework/src/Illuminate/Container/Util.php(37): Illuminate\\Container\\BoundMethod::Illuminate\\Container\\{closure}()
#10 /var/www/html/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(95): Illuminate\\Container\\Util::unwrapIfClosure()
#11 /var/www/html/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(39): Illuminate\\Container\\BoundMethod::callBoundMethod()
#12 /var/www/html/vendor/laravel/framework/src/Illuminate/Container/Container.php(596): Illuminate\\Container\\BoundMethod::call()
#13 /var/www/html/vendor/laravel/framework/src/Illuminate/Console/Command.php(134): Illuminate\\Container\\Container->call()
#14 /var/www/html/vendor/symfony/console/Command/Command.php(258): Illuminate\\Console\\Command->execute()
#15 /var/www/html/vendor/laravel/framework/src/Illuminate/Console/Command.php(121): Symfony\\Component\\Console\\Command\\Command->run()
#16 /var/www/html/vendor/symfony/console/Application.php(920): Illuminate\\Console\\Command->run()
#17 /var/www/html/vendor/symfony/console/Application.php(266): Symfony\\Component\\Console\\Application->doRunCommand()
#18 /var/www/html/vendor/symfony/console/Application.php(142): Symfony\\Component\\Console\\Application->doRun()
#19 /var/www/html/vendor/laravel/framework/src/Illuminate/Console/Application.php(93): Symfony\\Component\\Console\\Application->run()
#20 /var/www/html/vendor/laravel/framework/src/Illuminate/Foundation/Console/Kernel.php(129): Illuminate\\Console\\Application->run()
#21 /var/www/html/artisan(37): Illuminate\\Foundation\\Console\\Kernel->handle()
#22 {main}
"} 
[2020-10-01 08:41:07] production.ERROR: Spatie\Mailcoach\Jobs\SendCampaignJob has been attempted too many times or run too long. The job may have previously timed out. {"exception":"[object] (Illuminate\\Queue\\MaxAttemptsExceededException(code: 0): Spatie\\Mailcoach\\Jobs\\SendCampaignJob has been attempted too many times or run too long. The job may have previously timed out. at /var/www/html/vendor/laravel/framework/src/Illuminate/Queue/Worker.php:648)
[stacktrace]
#0 /var/www/html/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(436): Illuminate\\Queue\\Worker->maxAttemptsExceededException()
#1 /var/www/html/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(346): Illuminate\\Queue\\Worker->markJobAsFailedIfAlreadyExceedsMaxAttempts()
#2 /var/www/html/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(306): Illuminate\\Queue\\Worker->process()
#3 /var/www/html/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(132): Illuminate\\Queue\\Worker->runJob()
#4 /var/www/html/vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php(112): Illuminate\\Queue\\Worker->daemon()
#5 /var/www/html/vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php(96): Illuminate\\Queue\\Console\\WorkCommand->runWorker()
#6 /var/www/html/vendor/laravel/horizon/src/Console/WorkCommand.php(46): Illuminate\\Queue\\Console\\WorkCommand->handle()
#7 [internal function]: Laravel\\Horizon\\Console\\WorkCommand->handle()
#8 /var/www/html/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(37): call_user_func_array()
#9 /var/www/html/vendor/laravel/framework/src/Illuminate/Container/Util.php(37): Illuminate\\Container\\BoundMethod::Illuminate\\Container\\{closure}()
#10 /var/www/html/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(95): Illuminate\\Container\\Util::unwrapIfClosure()
#11 /var/www/html/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(39): Illuminate\\Container\\BoundMethod::callBoundMethod()
#12 /var/www/html/vendor/laravel/framework/src/Illuminate/Container/Container.php(596): Illuminate\\Container\\BoundMethod::call()
#13 /var/www/html/vendor/laravel/framework/src/Illuminate/Console/Command.php(134): Illuminate\\Container\\Container->call()
#14 /var/www/html/vendor/symfony/console/Command/Command.php(258): Illuminate\\Console\\Command->execute()
#15 /var/www/html/vendor/laravel/framework/src/Illuminate/Console/Command.php(121): Symfony\\Component\\Console\\Command\\Command->run()
#16 /var/www/html/vendor/symfony/console/Application.php(920): Illuminate\\Console\\Command->run()
#17 /var/www/html/vendor/symfony/console/Application.php(266): Symfony\\Component\\Console\\Application->doRunCommand()
#18 /var/www/html/vendor/symfony/console/Application.php(142): Symfony\\Component\\Console\\Application->doRun()
#19 /var/www/html/vendor/laravel/framework/src/Illuminate/Console/Application.php(93): Symfony\\Component\\Console\\Application->run()
#20 /var/www/html/vendor/laravel/framework/src/Illuminate/Foundation/Console/Kernel.php(129): Illuminate\\Console\\Application->run()
#21 /var/www/html/artisan(37): Illuminate\\Foundation\\Console\\Kernel->handle()
#22 {main}
"}

I have the impression that the Job continues to runs after this errors into the logs as my "sends" continue to be inserted by that jobs after that :

_MySQL_5_7_26-29-log__BMYSCTRP01_-_ctrmail_PROD_ctrmail_mailcoach_campaigns

The timeouts in my horizon.php are very high...

//config/horizon.php
    'environments' => [
        'production' => [
            'supervisor-1' => [
                'connection' => 'redis',
                'queue' => ['default'],
                'balance' => 'simple',
                'processes' => 5,
                'tries' => 1,
                'timeout' => 60 * 60 * 3,
            ],
            'mailcoach' => [
                'connection' => 'mailcoach-redis',
                'queue' => ['send-campaign', 'mailcoach-feedback', 'mailcoach'],
                'balance' => 'auto',
                'minProcesses' => 2,
                'maxProcesses' => env("MAILCOACH_HORIZON_PROCESSES", 5),
                'tries' => 2,
                'timeout' => 60 * 60 * 3,
            ],
            'mailcoach-sendmail' => [
                'connection' => 'mailcoach-redis',
                'queue' => ['send-mail'],
                'balance' => 'auto',
                'minProcesses' => 1,
                'maxProcesses' => env("MAILCOACH_HORIZON_SENDMAIL_PROCESSES", 10),
                'tries' => 2,
                'timeout' => 60 * 60,
            ]
        ],

Can you help me to understand what happens?

freekmurze commented 4 years ago

What is the value of retry_after in your queue config file? This should be set to a higher number than the default as well.

electronick86 commented 4 years ago

@freekmurze, you impressed me one more time 🥇 

>>> config("queue.connections.mailcoach-redis")
=> [
     "driver" => "redis",
     "connection" => "default",
     "queue" => "default",
     "retry_after" => 660,
     "block_for" => null,
   ]
>>>

This means that the retry after should always be higher than the timeout? In my mind, the retry_after value was the amount of seconds after a failed job.

This is for sure the cause of #248 .

EDIT : https://laravel.com/docs/8.x/queues#job-expirations-and-timeouts it's now clear.