Queue process unexpectedly exits with no errors logged

[jmrs-22]

How do you use Sentry?

Sentry SaaS (sentry.io)

SDK version

^1.9

Steps to reproduce

Environment
Laravel 5.2.45
PHP 7.1.33
sentry-laravel ^1.9

Expected result

An error is raised from a Queue job, this is expected to be catched and handled by a service which logs it on different channels (file, db and Sentry). The problem is that when the captureException line is reached, the process ends unexpectedly leaving the logging process unfinished and also the finally clause isn't reached.

Job

public function handle (
		WMLogger $logger, IAccountRepository $clientRepository, ILoanBillingInfoRepository $loanBillingInfoRepository,
		IArFinancialClientAPIService $arFinancialClientAPIService,
		IArFinancialBillingAPIService $arFinancialBillingAPIService
	)
	{
		try {
			$this->lock();
			$this->clientRepository = $clientRepository;
			$this->arFinancialClientAPIService = $arFinancialClientAPIService;
			$this->arFinancialBillingAPIService = $arFinancialBillingAPIService;
			$this->infoDb = $loanBillingInfoRepository->getById($this->infoId, [
				'loans_billing_info.id', 'loans_billing_info.billing_document_type_id', 'loans_billing_info.uuid',
				'loans_billing_info.reference_date', 'loans_billing_info.billing_date',
				'loans_billing_info.billing_due_date', 'loans_billing_info.client_id',
				'loans_billing_info.billing_client_id', 'loans_billing_info.discount_amount',
				'loans_billing_info.allowance_amount', 'loans_billing_info.adjustment_amount',
				'loans_billing_info.rounding_amount', 'loans_billing_info.is_billed',
				'loans_billing_info.billing_document_id', 'loans_billing_info.has_errors',
				'loans_billing_info.error_details'
			]);
			$billedDocumentId = $this->billedDocumentId;

			if (empty($this->infoDb) || $this->infoDb->is_billed) {
				return;
			}

			if (!empty($billedDocumentId)) {
				$document = $this->arFinancialBillingAPIService->getDocumentByBillingId($billedDocumentId);
				$this->saveDocument($document);

				return;
			}

			$this->setBillingDates();
			$this->handleBillingClient();
			$document = $this->createDocument();
			$this->saveDocument($document);
		} catch (Throwable $exception) {
			if (!$this->isErrorLogged && !$this->checkIfLockingError($exception)) {
				$this->registerErrorDetails($exception);
			}

			$logger->logError(
				__METHOD__, $exception, [
					'info_id' => $this->infoId, 'operator_id' => $this->operatorId,
					'billed_document_id' => $this->billedDocumentId
				]
			);

			$this->delete();
		} finally {
			$this->releaseLock();
		}
	}

Logging Service

public function logError(string $method, Throwable $error, array $payload = NULL)
{
    $context = array_merge($this->getContext($method, $error->getFile(), $error->getLine()), [
        'payload' => $payload,
        'type' => get_class($error), 
        'error' => $error->getMessage(),
        'stack_trace' => $error->getTraceAsString()
    ]);

    Log::error($this->getLogDescription($method, 'Failure'), $context);
    ErrorRegister::save($error);

    Sentry::withScope(function (Scope $scope) use ($payload, $error): void {
        if (!empty($payload)) {
            $scope->setContext('payload', $payload);
        }

        Sentry::captureException($error);
    });
}

l've working with Sentry on jobs for the last 6 months and no problems until now. I don't know why this exact type of error is causing this issue. The thing is that this doesn't happen with every kind of error, I ran into it on this particular scenario.

This is the actual exception that fires the logging:

ErrorException: Undefined index: CUIT in /var/www/waynimovil-api/app/Domain/Billing/ArBillableClient.php:37
Stack trace:
0 /var/www/waynimovil-api/app/Domain/Billing/ArBillableClient.php(37): Illuminate\Foundation\Bootstrap\HandleExceptions->handleError(8, 'Undefined index...', '/var/www/waynim...', 37, Array)
1 /var/www/waynimovil-api/app/Services/Finance/AR/API/ArFinancialClientAPIService.php(70): We\Domain\Billing\ArBillableClient::setFromSystem(Array)
2 /var/www/waynimovil-api/app/Jobs/Finance/AR/Billing/Loans/ArBillLoanJob.php(174): We\Services\Finance\AR\API\ArFinancialClientAPIService->createClient(Object(We\Domain\Accounts\Account))
3 /var/www/waynimovil-api/app/Jobs/Finance/AR/Billing/Loans/ArBillLoanJob.php(157): We\Jobs\Finance\AR\Billing\Loans\ArBillLoanJob->fetchBillingClient(Object(We\Domain\Accounts\Account))
4 /var/www/waynimovil-api/app/Jobs/Finance/AR/Billing/Loans/ArBillLoanJob.php(108): We\Jobs\Finance\AR\Billing\Loans\ArBillLoanJob->handleBillingClient()
5 [internal function]: We\Jobs\Finance\AR\Billing\Loans\ArBillLoanJob->handle(Object(We\Services\WMLogger), Object(We\Domain\Accounts\AccountRepository), Object(We\Domain\Billing\LoanBillingInfoRepository), Object(We\Services\Finance\AR\API\ArFinancialClientAPIService), Object(We\Services\Finance\AR\API\ArFinancialBillingAPIService))
6 /var/www/waynimovil-api/vendor/laravel/framework/src/Illuminate/Container/Container.php(507): call_user_func_array(Array, Array)
7 /var/www/waynimovil-api/vendor/laravelcollective/bus/src/Dispatcher.php(200): Illuminate\Container\Container->call(Array)
8 [internal function]: Collective\Bus\Dispatcher->Collective\Bus\{closure}(Object(We\Jobs\Finance\AR\Billing\Loans\ArBillLoanJob))
9 /var/www/waynimovil-api/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(150): call_user_func(Object(Closure), Object(We\Jobs\Finance\AR\Billing\Loans\ArBillLoanJob))
10 [internal function]: Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}(Object(We\Jobs\Finance\AR\Billing\Loans\ArBillLoanJob))
11 /var/www/waynimovil-api/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(102): call_user_func(Object(Closure), Object(We\Jobs\Finance\AR\Billing\Loans\ArBillLoanJob))
12 /var/www/waynimovil-api/vendor/laravelcollective/bus/src/Dispatcher.php(212): Illuminate\Pipeline\Pipeline->then(Object(Closure))
13 /var/www/waynimovil-api/vendor/laravel/framework/src/Illuminate/Queue/CallQueuedHandler.php(41): Collective\Bus\Dispatcher->dispatchNow(Object(We\Jobs\Finance\AR\Billing\Loans\ArBillLoanJob))
14 /var/www/waynimovil-api/vendor/laravel/framework/src/Illuminate/Queue/Jobs/Job.php(130): Illuminate\Queue\CallQueuedHandler->call(Object(Illuminate\Queue\Jobs\DatabaseJob), Array)
15 /var/www/waynimovil-api/vendor/laravel/framework/src/Illuminate/Queue/Jobs/DatabaseJob.php(49): Illuminate\Queue\Jobs\Job->resolveAndFire(Array)
16 /var/www/waynimovil-api/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(213): Illuminate\Queue\Jobs\DatabaseJob->fire()
17 /var/www/waynimovil-api/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(156): Illuminate\Queue\Worker->process('database', Object(Illuminate\Queue\Jobs\DatabaseJob), '1', 0)
18 /var/www/waynimovil-api/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(111): Illuminate\Queue\Worker->pop(NULL, 'billing', 0, '3', '1')
19 /var/www/waynimovil-api/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(86): Illuminate\Queue\Worker->runNextJobForDaemon(NULL, 'billing', 0, '3', '1')
20 /var/www/waynimovil-api/vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php(119): Illuminate\Queue\Worker->daemon(NULL, 'billing', 0, '256', '3', '1')
21 /var/www/waynimovil-api/vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php(78): Illuminate\Queue\Console\WorkCommand->runWorker(NULL, 'billing', 0, '256', true)
22 [internal function]: Illuminate\Queue\Console\WorkCommand->fire()
23 /var/www/waynimovil-api/vendor/laravel/framework/src/Illuminate/Container/Container.php(507): call_user_func_array(Array, Array)
24 /var/www/waynimovil-api/vendor/laravel/framework/src/Illuminate/Console/Command.php(169): Illuminate\Container\Container->call(Array)
25 /var/www/waynimovil-api/vendor/symfony/console/Command/Command.php(256): Illuminate\Console\Command->execute(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
26 /var/www/waynimovil-api/vendor/laravel/framework/src/Illuminate/Console/Command.php(155): Symfony\Component\Console\Command\Command->run(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
27 /var/www/waynimovil-api/vendor/symfony/console/Application.php(794): Illuminate\Console\Command->run(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
28 /var/www/waynimovil-api/vendor/symfony/console/Application.php(186): Symfony\Component\Console\Application->doRunCommand(Object(Illuminate\Queue\Console\WorkCommand), Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
29 /var/www/waynimovil-api/vendor/symfony/console/Application.php(117): Symfony\Component\Console\Application->doRun(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
30 /var/www/waynimovil-api/vendor/laravel/framework/src/Illuminate/Foundation/Console/Kernel.php(107): Symfony\Component\Console\Application->run(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
31 /var/www/waynimovil-api/artisan(35): Illuminate\Foundation\Console\Kernel->handle(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
32 {main}

This happend on live code, it was a bit difficult to reproduce on my local environment so I started running some tests where it is deployed. I thought that it could be a missing flush in order to clear events, I tried it but with no success. It seems that any reference to flush, captureMessage or captureException turns into the same result. When I remove Sentry references, the job ends gracefully. I also tried to add some Log references in Sentry vendor source files but these are not reached either.

Actual result

Live Test 1

Live Test 1 Result

Live Test 2

Live Test 2 Result

[cleptric]

Maybe you can try to upgrade to version 2.14.2 of the Laravel SDK, which also supports Laravel 5.0 - 5.8 and see if this fixes your issue.

[jmrs-22]

Thank you for your quick response. If I try to update, wouldn't I be restricted by PHP version? I'm working with 7.1.33 and I understand that starting from Sentry 2, PHP 7.2 is required.

[cleptric]

Ahh yes, you would need PHP 7.2 at least.
Are you able to provide us with a minimal repro case?

[jmrs-22]

Which things should I include in the repro case? Yesterday I tried to reproduce it on my local environment, using production read only database but everything worked as expected. I also tried to increase memory usage on queue:work | queue:listen commands but the error persists on live.

[cleptric]

Could your PHP settings on your production system be the issue, then? If it works for you locally.

[jmrs-22]

Is there a particular setting that I should be looking into? At least on my local environment the execution was not interrumpted, but I'll test it again just to be certain.

[cleptric]

I would start by comparing your php.ini files

[getsantry]

This issue has gone three weeks without activity. In another week, I will close it.

But! If you comment or otherwise update it, I will reset the clock, and if you remove the label Waiting for: Community, I will leave it alone ... forever!

---

"A weed is but an unloved flower." ― Ella Wheeler Wilcox 🥀