Level 1
Bump
Jan 3, 2024
12
Level 1
Eloquent does not save changes to database in Queue Event handlers
I have bound some function to Queue Events in laravel.
Queue::failing(function (JobFailed $event) {
Log::info("FAILED JOB");
Helpers::updateJobLogToFailed($event);
Log::info("UPDATED JOB LOG TO FAILED JOB");
});
public static function updateJobLogToFailed(JobFailed $event) {
$job_id = $event->job->getJobId();
\Log::info("FAILING JOB $job_id");
$payload = $event->job->payload();
$job_uuid = $payload['uuid'];
$job_name = $payload['displayName'];
\Log::info("$job_name has failed");
$log = JobLog::firstWhere('job_uuid', $payload['uuid']);
if (!isset($log)) {
\Log::info("Job log not found for: $job_name");
return;
}
$job_failed_status = Lov::firstWhere([
'key' => 'failed',
'identifier' => 'JOB_STATUS'
]);
$log->status = $job_failed_status->key;
$log->exception = $event->exception->getMessage();
$log->stack_trace = $event->exception->getTraceAsString();
$log->save();
\Log::info("FAILED JOB $job_id: $job_uuid");
}
I am using laravel horizon to manage queues. One of my job failed after a timeout (2000s). This is what the logs look like
[2024-01-03 15:08:22] local.INFO: FAILED JOB
[2024-01-03 15:08:22] local.INFO: FAILING JOB d150b091-df57-43af-964e-821f3cd4cad1
[2024-01-03 15:08:22] local.INFO: App\Jobs\JobName has failed
[2024-01-03 15:08:22] local.INFO: FAILED JOB d150b091-df57-43af-964e-821f3cd4cad1: d150b091-df57-43af-964e-821f3cd4cad1
Note the last line in the logs, that line is logged at the end of "updateJobLogToFailed" method defined above. Logging this line also means that the log to be updated was found in the DB since the if condition for !isset($log) did not satisfy.
Despite all that the log is not updated to 'failed' and remains as if it was never updated in the database even when the logs indicate otherwise.
I would appreciate any help regarding this, for now I have no idea where to begin solving this. I anyone is willing to help, please let me know if you require additional information.
Level 70
@concurrent_manifest By any chance, do you use a different database connection for JobLog? Can you confirm what connection it's using?
Level 1
@tisuchi Hello. We are using the default mysql connection that is specified in database.php.
'mysql' => [
'driver' => 'mysql',
'host' => env('DB_HOST', '127.0.0.1'),
'port' => env('DB_PORT', '3306'),
'database' => env('DB_DATABASE', 'trailer'),
'username' => env('DB_USERNAME', 'phpmyadmin'),
'password' => env('DB_PASSWORD', 'supersecure'),
'unix_socket' => env('DB_SOCKET', ''),
'charset' => 'utf8mb4',
'collation' => 'utf8mb4_unicode_ci',
'prefix' => '',
'strict' => false,
'engine' => null,
],
Level 1
Bump
Level 122
what type of column is job_uuid, and do you have a separate primary key?
my thoughts are that it IS updating the database, but not the record you expected
Level 1
@Snapey It is a string containing the uuid for the job, and yes we do have a separate auto increment primary key for job_logs as well. I checked the database to see if the job_uuid was ever duplicated, it was not.
Level 122
@concurrent_Manifest temporarily use
$log = JobLog::firstWhere('job_uuid', $payload['uuid']);
\Log::info('loaded joblog ' . $log->id);
Level 1
[2024-01-17 18:44:04] local.INFO: FAILED JOB
[2024-01-17 18:44:04] local.INFO: FAILING JOB b9e62c4a-a682-475d-bd1f-3b9b3db16a97
[2024-01-17 18:44:04] local.INFO: App\Jobs\JobName has failed
[2024-01-17 18:44:05] local.INFO: loaded joblog in updateJobLogToFailed
[2024-01-17 18:44:05] local.INFO: loaded joblog 4787
[2024-01-17 18:44:05] local.INFO: FAILED JOB b9e62c4a-a682-475d-bd1f-3b9b3db16a97: b9e62c4a-a682-475d-bd1f-3b9b3db16a97
[2024-01-17 18:44:05] local.INFO: UPDATED JOB LOG TO FAILED JOB
The id logged for the job log is correct, the update however just as before is not persisted.
Level 122
@concurrent_Manifest I thought we established that the error was because your transaction is rolled back?
Level 1
@Snapey There are rollbacks in our code when an exception occurs inside the handle() function, meaning any error caused by our business logic.
In this case however, the exception that caused this job to fail was as I discussed previously in the first post of this thread is:
Illuminate\Queue\MaxAttemptsExceededException: App\Jobs\JobName has been attempted too many times or run too long. The job may have previously timed out.
Horizon has stored this error in the failed jobs entry.
I initially thought that the transaction rolling back may be causing updates to not be persisted but since the exception is not thrown from the handle() function I am still at a loss at trying to graspwhy this issue seems to be happening.
Apologies for any lack of understanding for how things work under the hood with horizon and db transactions from my end.
Level 1
The job that was responsible for this log, the one that failed does use transactions. Could that be responsible for this behavior?
Level 122
@concurrent_Manifest yes the update to the database could be rolled back
Please or to participate in this conversation.