Handling activity log exceptions

[anthonytp]

We've had a few instances when using the activity log where a SQL Serialization failure exception has been thrown.
The error is:

SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction

caused when trying to insert into the activity_log table

insert into activity_log (log_name, properties, causer_id, causer_type, subject_id, subject_type, description, impersonator_id, updated_at, created_at)
values (audit, {"attributes":{"updated_at":"2022-03-09T15:00:17.000000Z"},"old":{"updated_at":"2022-03-09T14:59:03.000000Z"}},
3393, user, 34350, App\UserChecks, App\UserChecks.updated, ?, 2022-03-09 15:00:27, 2022-03-09 15:00:27))

I realise I need to investigate the ultimate cause of the deadlock, but for now to avoid losing audit log entries I want to catch the exception and retry the insert - what would be the best way to do this?

I'm still reading through the code so I may well be able to answer my own question soon...

[Gummibeer]

This is more a database than a code problem. Which database and table engine do you use?
As most common is MySQL with InnoDB: https://dev.mysql.com/doc/refman/5.7/en/innodb-locking.html

I would like to pull in @tpetry as he knows more about databases. But so far I get it a switch to an unordered UUID primary key index and dropping the auto increment could solve your issue.

All this is supported by the package as you can customize the migrations and use your own model.

[anthonytp]

This is more a database than a code problem.

Yes, but at the moment I would like to be able to handle this (or any) exception to ensure all events are logged.

Which database and table engine do you use?

MySQL and InnoDB

... a switch to an unordered UUID primary key index and dropping the auto increment could solve your issue.

Interesting idea. You're right, there's no reason we need to have a numerical ID on this table. Log events can be ordered by date fields. Which has got me thinking it would be better to have a timestamp of when the activity happened (in code) and not just a created_at date/time when it was written to the database.

I'll leave this question open for now, in case someone else has a suggestion, but the GUID idea seems like it would be a simple change to fix this. Thanks

[Gummibeer]

There's a trait in Laravel core - some with Concurrency - search for "deadlock" in vendor directory. As the deadlock isn't a specific exception this trait should help you adding some special logic for dreadlocks.

[tpetry]

Without further information which other transaction (query) was involved in the deadlock, I can only guess. Normally, this is a problem with Next-Gap locks for auto_increment primary keys, but in this case, it shouldn't be a problem. But I spotted a new column in the error message, the impersonator_id which is not part of the official migration files. In case this is a foreign key, you can get some ne cases of deadlocks. Solving deadlocks is not that easy...

I do not support replacing the auto_increment primary key with an unordered UUID because inserting records in a random PK order is slow on InnoDB. But if you replace the unordered UUID with an ordered one, it's ok.

Furthermore, and this is valid for all deadlocks, I support changing the default transaction isolation level. Only MySQL and related MySQL databases are using REPEATABLE READ by default, everyone is else is using READ COMMITTED. You'll get a lot less deadlocks with READ COMMITTED as the isolation safety is not that high. But you most probably don't need REPEATABLE READ?

[anthonytp]

Thanks @tpetry that gives me some more to work with.

Without further information which other transaction (query) was involved in the deadlock

I don't have that information at the moment, my question was prompted by a log of the exception in Sentry. I'm willing to give the ordered UUID key a try and see if that helps.

... a new column in the error message, the impersonator_id

Yes, it is a foreign key. Certain users can impersonate others on the website so we track this when activity is logged.

Solving deadlocks is not that easy...

Yes! That's why I thought adding an exception handler and retrying might be an easy solution :)

You'll get a lot less deadlocks with READ COMMITTED as the isolation safety is not that high

I'll check the DB, thanks for this 👍

[anthonytp]

We've changed the PK to an ordered UUID and will monitor it to see if deadlocks occur again. Thanks for your help @Gummibeer and @tpetry