Cronjob causes many console.CRITICAL errors in log file #6907

LIVID-Media · 2024-02-18T20:46:38Z

Affected version(s)

5.3.0

Description

Since the update from 5.2.8 to 5.3 there are a lot of critical errors in the log file after cronjob is executed. The main problem is "more than 'max_user_connections' active connections".

Here's an excerpt from the log file:

[2024-02-18T20:40:23.227068+01:00] console.CRITICAL: Error thrown while running command "messenger:consume --time-limit=60 --sleep=5 contao_prio_high". Message: "An exception occurred in the driver: SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections" {"exception":"[object] (Doctrine\\DBAL\\Exception\\DriverException(code: 1203): An exception occurred in the driver: SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections at /home/www/xxx.de/vendor/doctrine/dbal/src/Driver/API/MySQL/ExceptionConverter.php:117)\n[previous exception] [object] (Doctrine\\DBAL\\Driver\\PDO\\Exception(code: 1203): SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections at /home/www/xxx.de/vendor/doctrine/dbal/src/Driver/PDO/Exception.php:28)\n[previous exception] [object] (PDOException(code: 1203): SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections at /home/www/xxx.de/vendor/doctrine/dbal/src/Driver/PDO/MySQL/Driver.php:33)","command":"messenger:consume --time-limit=60 --sleep=5 contao_prio_high","message":"An exception occurred in the driver: SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections"} []
[2024-02-18T20:40:23.228826+01:00] console.CRITICAL: Error thrown while running command "messenger:consume --time-limit=60 --sleep=10 contao_prio_normal". Message: "An exception occurred in the driver: SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections" {"exception":"[object] (Doctrine\\DBAL\\Exception\\DriverException(code: 1203): An exception occurred in the driver: SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections at /home/www/xxx.de/vendor/doctrine/dbal/src/Driver/API/MySQL/ExceptionConverter.php:117)\n[previous exception] [object] (Doctrine\\DBAL\\Driver\\PDO\\Exception(code: 1203): SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections at /home/www/xxx.de/vendor/doctrine/dbal/src/Driver/PDO/Exception.php:28)\n[previous exception] [object] (PDOException(code: 1203): SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections at /home/www/xxx.de/vendor/doctrine/dbal/src/Driver/PDO/MySQL/Driver.php:33)","command":"messenger:consume --time-limit=60 --sleep=10 contao_prio_normal","message":"An exception occurred in the driver: SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections"} []
[2024-02-18T20:40:28.286152+01:00] console.CRITICAL: Error thrown while running command "messenger:consume --time-limit=60 --sleep=5 contao_prio_high". Message: "An exception occurred in the driver: SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections" {"exception":"[object] (Doctrine\\DBAL\\Exception\\DriverException(code: 1203): An exception occurred in the driver: SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections at /home/www/xxx.de/vendor/doctrine/dbal/src/Driver/API/MySQL/ExceptionConverter.php:117)\n[previous exception] [object] (Doctrine\\DBAL\\Driver\\PDO\\Exception(code: 1203): SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections at /home/www/xxx.de/vendor/doctrine/dbal/src/Driver/PDO/Exception.php:28)\n[previous exception] [object] (PDOException(code: 1203): SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections at /home/www/xxx.de/vendor/doctrine/dbal/src/Driver/PDO/MySQL/Driver.php:33)","command":"messenger:consume --time-limit=60 --sleep=5 contao_prio_high","message":"An exception occurred in the driver: SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections"} []
[2024-02-18T20:40:28.286574+01:00] console.CRITICAL: Error thrown while running command "messenger:consume --time-limit=60 --sleep=10 contao_prio_normal". Message: "An exception occurred in the driver: SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections" {"exception":"[object] (Doctrine\\DBAL\\Exception\\DriverException(code: 1203): An exception occurred in the driver: SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections at /home/www/xxx.de/vendor/doctrine/dbal/src/Driver/API/MySQL/ExceptionConverter.php:117)\n[previous exception] [object] (Doctrine\\DBAL\\Driver\\PDO\\Exception(code: 1203): SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections at /home/www/xxx.de/vendor/doctrine/dbal/src/Driver/PDO/Exception.php:28)\n[previous exception] [object] (PDOException(code: 1203): SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections at /home/www/xxx.de/vendor/doctrine/dbal/src/Driver/PDO/MySQL/Driver.php:33)","command":"messenger:consume --time-limit=60 --sleep=10 contao_prio_normal","message":"An exception occurred in the driver: SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections"} []
[2024-02-18T20:40:28.301905+01:00] console.CRITICAL: Error thrown while running command "messenger:consume --time-limit=60 --sleep=20 contao_prio_low". Message: "An exception occurred in the driver: SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections" {"exception":"[object] (Doctrine\\DBAL\\Exception\\DriverException(code: 1203): An exception occurred in the driver: SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections at /home/www/xxx.de/vendor/doctrine/dbal/src/Driver/API/MySQL/ExceptionConverter.php:117)\n[previous exception] [object] (Doctrine\\DBAL\\Driver\\PDO\\Exception(code: 1203): SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections at /home/www/xxx.de/vendor/doctrine/dbal/src/Driver/PDO/Exception.php:28)\n[previous exception] [object] (PDOException(code: 1203): SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections at /home/www/xxx.de/vendor/doctrine/dbal/src/Driver/PDO/MySQL/Driver.php:33)","command":"messenger:consume --time-limit=60 --sleep=20 contao_prio_low","message":"An exception occurred in the driver: SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections"} []
[2024-02-18T20:40:33.323472+01:00] console.CRITICAL: Error thrown while running command "messenger:consume --time-limit=60 --sleep=10 contao_prio_normal". Message: "An exception occurred in the driver: SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections" {"exception":"[object] (Doctrine\\DBAL\\Exception\\DriverException(code: 1203): An exception occurred in the driver: SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections at /home/www/xxx.de/vendor/doctrine/dbal/src/Driver/API/MySQL/ExceptionConverter.php:117)\n[previous exception] [object] (Doctrine\\DBAL\\Driver\\PDO\\Exception(code: 1203): SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections at /home/www/xxx.de/vendor/doctrine/dbal/src/Driver/PDO/Exception.php:28)\n[previous exception] [object] (PDOException(code: 1203): SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections at /home/www/xxx.de/vendor/doctrine/dbal/src/Driver/PDO/MySQL/Driver.php:33)","command":"messenger:consume --time-limit=60 --sleep=10 contao_prio_normal","message":"An exception occurred in the driver: SQLSTATE[HY000] [1203] User webxxx already has more than 'max_user_connections' active connections"} []

The error didn't occur in Contao 5.2. Maybe it has something to do with the new SuperviseWorkersCommand script?!

The text was updated successfully, but these errors were encountered:

leofeyer · 2024-02-20T10:33:39Z

@LIVID-Media What is the value of max_user_connections on your system?

@Toflar /cc

Toflar · 2024-02-20T10:35:39Z

I can hardly imagine this error did not happen before. In 5.2 we ran the commands every minute and did not supervise whether they were already running. Now we do. Or in other words, if you now have too many connections, you should've had this before as well :)

LIVID-Media · 2024-02-20T10:55:10Z

@leofeyer Only 15. I know that's not very much, but this was never a problem before.

@Toflar I check the log files regularly, the error only occurres since the update to 5.3.

I will contact my web host and ask them to increase the value.

fritzmg · 2024-02-20T10:57:37Z

Have the visitors increased? This could also be the reason, though Contao 5 having lots of message workers hogging your connections is not ideal of course 🙈 . Unfortunately a low number of max_user_connections is pretty common with cheap shared hostings. You could enable the HTTP cache in order to alleviate the issue.

Toflar · 2024-02-20T10:59:54Z

Maybe in 5.2 there were just less messages, was it used in prod? If you run ps aux | grep messenger regularly, you can see how many workers are started. But by default, autoscaling allows to start 30 processes = could use 30 connections on CLI alone (plus your web ones).
See https://github.com/contao/contao/blob/5.x/manager-bundle/skeleton/config/config.yaml#L63-L93

We can of course reduce the defaults there. 10 is a bit high. But this has been the case in 5.2 too, so I don't think there's anything wrong in the supervision introduced in 5.3.

LIVID-Media · 2024-02-20T11:22:25Z

@fritzmg No, the number of visitors has not changed.
@Toflar Yes, I have two live websites, both of which now have the same problem.

LIVID-Media · 2024-02-20T15:36:06Z

I've a Contao 5.2.8 test installation on the same server with the same setup. When I call contao-console contao:cron --force there, a maximum of four processes are displayed in MySQL.

In 5.3 it's getting more and more during the cron job until the connection is lost and the site is no longer accessible.

In my local system (with max_user_connections = 0), the problem also occurs. I'd already deactivated all extensions.

leofeyer · 2024-02-20T15:41:59Z

@Toflar Is there an easy way to disable the supervisor without disabling the background workers, so @LIVID-Media can test if the problem is really caused by the supervisor?

fritzmg · 2024-02-20T16:10:54Z

I did some local tests. When I execute contao:cron "Contao\CoreBundle\Cron\SuperviseWorkersCron" in Contao 5.3.0 the PHP processes slowly increase from 4 to 30 over the course of the next 55 seconds (even though there is no work to do).

But when I execute contao:cron "Contao\CoreBundle\Cron\MessengerCron" in Contao 5.2.10 the number of PHP process stays at 4 (1 process for contao:cron and 3 worker processes).

So I can confirm the issue.

leofeyer · 2024-02-20T16:35:40Z

@LIVID-Media While we debug the problem, you can disable the background workers by adding this in your config.yaml file:

contao:
    messenger:
        workers: []

fritzmg · 2024-02-20T16:37:08Z

Careful, this will disable email sending!

leofeyer · 2024-02-20T16:39:16Z

No, it won't. I have been using this for some time on contao.org and the emails are sent without any problems. Not asynchronously, of course.

fritzmg · 2024-02-20T17:00:21Z

Ah sorry, did not know that. Then yes, that's the way to go.

LIVID-Media · 2024-02-20T18:45:52Z

@leofeyer Thanks for the information. This solved the problem for now.

fritzmg · 2024-02-20T22:19:55Z

My bad, in my local setup the issue was actually the lack of support for Windows from toflar/cronjob-supervisor (see Toflar/cronjob-supervisor#1). With the added Windows support, I do not notice any run-away process creation via contao:supervise-worker.

fritzmg · 2024-02-21T13:43:21Z

@LIVID-Media is there a possibility to gain test access to your server environment?

LIVID-Media · 2024-02-21T13:52:23Z

@fritzmg Sure. Please tell me what you need.

fritzmg · 2024-02-21T18:03:02Z

I can confirm the issue with the credentials provided by @LIVID-Media. It's a Webgo shared hosting environment, where the ps command does not work:

$ ps
Error, do this: mount -t proc proc /proc

Thus Supervisor::isRunningPid() always returns false and therefore the Supervisor keeps starting processes every 5 seconds.

This will likely to be the case on all of Webgo's shared hosting environments (I was also able confirm this in the Webgo hostings of two of our customers).

@LIVID-Media as a first step you could ask Webgo's support to make the ps command work in the shell environment (I will do the same).

There could of course also be other shared hosting environments where ps does not work. We will probably have to implement a failover in the Supervisor, if ps does not work (not sure how though).

Toflar · 2024-02-26T17:28:54Z

With Toflar/cronjob-supervisor#2 we can probably fix this as posix_getpgid() might be supported. But then the question here is still what do we do if we still cannot supervise. We can now check this using Supervisor::canSupervise() in v2 but where would we check this?

We have 2 places where we can check it:

a) Check it at Container runtime. This is hard because the Supervisor instance is not created there at the moment so it means we need to do quite some work.
b) Check it when running contao:supervise-workers. This should be easy to implement.

And then the question is also what to do if the check fails.

Case a): When building the container, we could disable the entire worker configuration - > but where would we log?

Case b): In case of doing it in the contao:supervise-workers command we have also all sorts of questions to clarify -> where do we log? (probably just inject the logger, but what level then?) and should we still run 1 worker but ignore the autoscaling? (= it could still lead to too many processes running if they all run more than a minute) or should we disable it completely? Should it exit with exit code 0 or with an error? Would contao:cron fail then?

LIVID-Media · 2024-02-27T07:47:33Z

Even though there may soon be a solution. Nevertheless, here is the answer from WebGo in short:
It's not possible to limited the ps command to a specific chroot environment on shared hosting. This would display all running processes of the server, including processes of other customers and the root user. Therefore they can't activate ps in shared hosting.

leofeyer · 2024-03-07T15:01:18Z

As discussed in the Contao call, we want to set contao.messenger.workers to an empty array when building the container and supervising is not supported. This can then be checked with container:debug (similar to the image library).

Description ----------- Fixes #6907. Ready for review but needs an update of the `composer.json` entries before merging. Requires Toflar/cronjob-supervisor#2 to be released as 2.0.0 which I'll only do once this PR is approved concept-wise. Commits ------- b63f645 Update to toflar/cronjob-supervisor v2 and disable workers if not sup… 7b81d99 Use static helpers c1e55c0 Update to stable release

Description ----------- Fixes contao/contao#6907. Ready for review but needs an update of the `composer.json` entries before merging. Requires Toflar/cronjob-supervisor#2 to be released as 2.0.0 which I'll only do once this PR is approved concept-wise. Commits ------- b63f6452 Update to toflar/cronjob-supervisor v2 and disable workers if not sup… 7b81d990 Use static helpers c1e55c04 Update to stable release

LIVID-Media added bug unconfirmed labels Feb 18, 2024

leofeyer added this to the 5.3 milestone Feb 20, 2024

fritzmg removed the unconfirmed label Feb 20, 2024

fritzmg added the unconfirmed label Feb 20, 2024

fritzmg removed the unconfirmed label Feb 21, 2024

leofeyer added the up for discussion Issues and PRs which will be discussed in our monthly Mumble calls. label Feb 27, 2024

leofeyer assigned Toflar Mar 7, 2024

leofeyer removed the up for discussion Issues and PRs which will be discussed in our monthly Mumble calls. label Mar 7, 2024

Toflar mentioned this issue Mar 11, 2024

Disable background workers if they are not supported #6995

Merged

leofeyer linked a pull request Mar 20, 2024 that will close this issue

Disable background workers if they are not supported #6995

Merged

leofeyer closed this as completed Mar 20, 2024

github-actions bot locked as resolved and limited conversation to collaborators Apr 20, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Cronjob causes many console.CRITICAL errors in log file #6907

Cronjob causes many console.CRITICAL errors in log file #6907

LIVID-Media commented Feb 18, 2024

leofeyer commented Feb 20, 2024

Toflar commented Feb 20, 2024

LIVID-Media commented Feb 20, 2024

fritzmg commented Feb 20, 2024 •

edited

Loading

Toflar commented Feb 20, 2024

LIVID-Media commented Feb 20, 2024

LIVID-Media commented Feb 20, 2024

leofeyer commented Feb 20, 2024

fritzmg commented Feb 20, 2024 •

edited

Loading

leofeyer commented Feb 20, 2024

fritzmg commented Feb 20, 2024

leofeyer commented Feb 20, 2024

fritzmg commented Feb 20, 2024

LIVID-Media commented Feb 20, 2024

fritzmg commented Feb 20, 2024

fritzmg commented Feb 21, 2024

LIVID-Media commented Feb 21, 2024

fritzmg commented Feb 21, 2024

Toflar commented Feb 26, 2024

LIVID-Media commented Feb 27, 2024

leofeyer commented Mar 7, 2024

Cronjob causes many console.CRITICAL errors in log file #6907

Cronjob causes many console.CRITICAL errors in log file #6907

Comments

LIVID-Media commented Feb 18, 2024

Affected version(s)

Description

leofeyer commented Feb 20, 2024

Toflar commented Feb 20, 2024

LIVID-Media commented Feb 20, 2024

fritzmg commented Feb 20, 2024 • edited Loading

Toflar commented Feb 20, 2024

LIVID-Media commented Feb 20, 2024

LIVID-Media commented Feb 20, 2024

leofeyer commented Feb 20, 2024

fritzmg commented Feb 20, 2024 • edited Loading

leofeyer commented Feb 20, 2024

fritzmg commented Feb 20, 2024

leofeyer commented Feb 20, 2024

fritzmg commented Feb 20, 2024

LIVID-Media commented Feb 20, 2024

fritzmg commented Feb 20, 2024

fritzmg commented Feb 21, 2024

LIVID-Media commented Feb 21, 2024

fritzmg commented Feb 21, 2024

Toflar commented Feb 26, 2024

LIVID-Media commented Feb 27, 2024

leofeyer commented Mar 7, 2024

fritzmg commented Feb 20, 2024 •

edited

Loading

fritzmg commented Feb 20, 2024 •

edited

Loading