Hi @demon_ru
Thank you very much for posting the issue.
Since you mentioned the cron jobs, do you know if the error is generated by them (based on the timing)? If yes, do you know which cron job it is?
What kind of mosparo setup do you use? Do you have a multi-node setup where the cron job runs across multiple nodes simultaneously? Do you see any additional or previous log messages in the log file for this error message?
Thank you very much for your feedback.
Kind regards,
zepich / mosparo Team
*/15 * * * * /usr/bin/php /var/www/captcha/bin/console mosparo:cleanup-database
I’m not sure if the reason is the cron. And the timings do not confirm this version.
[2025-12-15T03:21:40.420412+03:00]
[2025-12-15T03:22:02.429761+03:00]
[2025-12-15T13:15:09.920308+03:00]
[2025-12-15T13:16:25.019714+03:00]
[2025-12-15T13:18:15.135119+03:00]
[2025-12-15T13:18:43.237138+03:00]
[2025-12-15T13:18:46.107563+03:00]
[2025-12-15T17:52:12.316441+03:00]
[2025-12-15T17:53:15.113371+03:00]
[2025-12-15T17:54:23.095406+03:00]
[2025-12-15T17:54:29.090746+03:00]
[2025-12-15T17:56:27.173976+03:00]
[2025-12-15T17:56:57.089768+03:00]
[2025-12-15T17:57:16.262044+03:00]
[2025-12-15T21:20:08.886769+03:00]
Mosparo works using nginx+php-fpm on one dedicated server (ubuntu server). On a separate website. It has several (couple dozen) projects configured for individual sites. No any nodes, dockers, kubernetes…
Each such line of the log is necessarily surrounded by other “INFO”
[2025-12-15T13:18:46.085405+03:00] request.INFO: Matched route "frontend_api_check_form_data". {"route":"frontend_api_check_form_data","route_parameters":{"_route":"frontend_api_check_form_data","_controller":"Mosparo\Controller\Api\V1\Frontend\FrontendApiController::checkFormData"},"request_uri":"https://captcha.domain.org/api/v1/frontend/check-form-data","method":"POST"} []
[2025-12-15T13:18:46.094523+03:00] deprecation.INFO: Deprecated: Creation of dynamic property Mosparo\Helper\RuleTesterHelper::$ruleTesters is deprecated {"exception":"[object] (ErrorException(code: 0): Deprecated: Creation of dynamic property Mosparo\Helper\RuleTesterHelper::$ruleTesters is deprecated at /var/www/captcha/src/Helper/RuleTesterHelper.php:274)"} []
[2025-12-15T13:18:46.107563+03:00] request.CRITICAL: Uncaught PHP Exception Doctrine\DBAL\Exception\DeadlockException: "An exception occurred while executing a query: SQLSTATE[40001]: Serialization failure: XXXX
[2025-12-15T13:18:46.122280+03:00] deprecation.INFO: User Deprecated: Since nelmio/security-bundle 3.4.0: The "Nelmio\SecurityBundle\EventListener\XssProtectionListener" class is deprecated, use Content Security Policy without allowing "unsafe-inline" scripts instead. {"exception":"[object] (ErrorException(code: 0): User Deprecated: Since nelmio/security-bundle 3.4.0: The \"Nelmio\SecurityBundle\EventListener\XssProtectionListener\" class is deprecated, use Content Security Policy without allowing \"unsafe-inline\" scripts instead. at /var/www/captcha/vendor/nelmio/security-bundle/src/EventListener/XssProtectionListener.php:35)"} []
Hi @demon_ru
Thank you very much for all the details. The problem occurs because of the API request (as indicated by the Info message before the exception). mosparo stores info and other log messages only in the log file if they occurred right before the exception.
The only thing I can think of right now that we write to the database and that can be the same across multiple requests is the IP address for the lockout and delay features.
So I’ve checked the mosparo log files from one of my productive installations and found the same error you have (DeadlockException).
I then checked the web server log file at the same time and saw that the same IP made a lot of requests (10 – 20) within 2 – 3 seconds. Can you check your log files to see if you see the same behaviour? If that’s the case, then you can ignore this problem.
I will search for a solution for this problem in mosparo. But since it’s most likely affecting spam bots, it is not a big problem for regular users.
Kind regards,
zepich / mosparo Team
I examined access.log by the time of the last CRITICAL entry in the log.
1. I don’t see many requests to the server
2. It doesn’t really look like they were robots (but it’s possible).
3. It’s clear that one request received an error of 500
80.85.xxx.xxx - - [16/Dec/2025:05:03:08 +0300] "POST /api/v1/frontend/check-form-data HTTP/2.0" 200 93 "https://www.domain.com/" "\x22Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/142.0.0.0 Safari/537.36\x22"
80.85.xxx.xxx - - [16/Dec/2025:05:03:12 +0300] "POST /api/v1/frontend/check-form-data HTTP/2.0" 200 93 "https://www.domain.com/" "\x22Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/142.0.0.0 Safari/537.36\x22"
80.85.xxx.xxx - - [16/Dec/2025:05:03:12 +0300] "POST /api/v1/frontend/check-form-data HTTP/2.0" 500 1017 "https://www.domain.com/" "\x22Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/142.0.0.0 Safari/537.36\x22"
80.85.xxx.xxx - - [16/Dec/2025:05:03:14 +0300] "POST /api/v1/frontend/check-form-data HTTP/2.0" 200 93 "https://www.domain.com/" "\x22Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/142.0.0.0 Safari/537.36\x22"
If I understand correctly… It’s not just a lock timeout, it’s a deadlock. And it can only be if there is a simultaneous change in one transaction in two places of two records in a different sequence.
And the increased load on the server only increases the likelihood of this.
Thanks for your attention to this issue (Ρ) Trump.
I hope you will find the source and solution to this problem. Thank you very much
Hi @demon_ru
Thank you very much for the details.
Did you anonymize the IP address before posting the log lines here, or do you store only two bits of the address in your log file? If you see the entire IP address, please run a whois (https://www.ipaddress.com/) to see who it belongs to. If it belongs to a hoster, it’s very likely a bot. If the IP address is in the range of 80.85.244.0 – 80.85.247.255, then it’s 100% a bot – since I had the same spam bot on multiple of my websites and the ranges belong to a data centerβ¦ π They are also listed on the stopforumspam.com list.
These two requests were executed at the same second, which is interesting since in a typical user scenario, same-second form validations are usually not the case:
80.85.xxx.xxx - - [16/Dec/2025:05:03:12 +0300] "POST /api/v1/frontend/check-form-data HTTP/2.0" 200 93 "https://www.domain.com/" "\x22Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/142.0.0.0 Safari/537.36\x22"
80.85.xxx.xxx - - [16/Dec/2025:05:03:12 +0300] "POST /api/v1/frontend/check-form-data HTTP/2.0" 500 1017 "https://www.domain.com/" "\x22Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/142.0.0.0 Safari/537.36\x22"
My explanation yesterday was that it was probably due to the Lockout or Delay security features in mosparo, because they write to the same row when one IP submits multiple requests at the same moment. But I tried that, and I’m not able to reproduce it with six parallel requests at the same time. So, I have some questions for you:
- Did you enable the security features “Delay” and/or “Lockout” in mosparo?
- Did you enable the GeoIP2 feature in mosparo by setting a GeoIP2 key in the administration?
- Is the MySQL/MariaDB server doing a lot of work? Does it have other large databases, and/or is the mosparo database pretty large? (I’m talking about a 10+ MB-sized database)
- Did you configure any special performance values for PHP FPM?
I have a possible solution for the problem, but first I need to identify the root cause and reproduce it. I don’t like adding any “fixes” that I cannot test to see if they’re working.
Kind regards,
zepich / mosparo Team
All values on the Security tab are set by default and have not changed.
Request delaying Enabled, IP lockout Disabled.
GeoIP2 disabled
MariaDB server doing a lot work, has other large databases. Although I don’t notice any performance drawdowns or problems with locks on other databases (sites).
Guess I have not configure any special performance values for PHP FPM.
Hi @demon_ru
Thank you very much for providing all the information, and sorry for the silence in the past few days.
I have good news! I found the problem, and a solution is pretty straightforward. We will release a new version tomorrow (most likely) or on Sunday.
The problem is that we update a row in one table and insert a row in another table in the same transaction, which locks the row we need to update. Since the insert query will take a moment, the other row is locked unnecessarily long. If a second request is made at the same time and needs to do the same (insert and update), the update will fail because the first request has locked the row.
Giving the update query its own transaction will fix the problem. We will add code to handle a possible deadlock, since it could still occur there. But in general, I can reproduce the issue within seconds with the old code, and after (temporarily) fixing it, the problem did not occur in 10+ minutes.
I will inform you as soon as the update is released.
Have a nice evening!
Kind regards,
zepich / mosparo Team
Hi @demon_ru
I added the fix for the deadlock issue and conducted more extensive testing. By splitting the bad query into two parts, the deadlock is gone.
The new version v1.4.8 was released some minutes ago.
I’m looking forward to reading your feedback.
Thank you very much for all your help in finding and solving the issue!
Kind regards,
zepich / mosparo Team
Updated three hours ago. There are no error logs (including deadlock) yet.
Thank you so much for your attentive attitude to the requests and the fastest possible response to them.
-
This reply was modified 1 month, 4 weeks ago by
demon_ru.
