Issue Plesk 17.8.11, upgraded from 17.5.3: high load average caused by /etc/cron.daily/50plesk-daily

[burnley]

CentOS 7.6, Plesk Onyx Version 17.8.11 Update #54 upgraded from 17.5.3.
We haven't seen this behaviour in 17.5.3 with the current set of tasks which reads:
/usr/local/psa/bin/sw-engine-pleskrun /usr/local/psa/admin/plib/DailyMaintainance/script.php -f CheckForUpdates,UpdateKeys,PleskUsage,Sitebuilder,MailUsage,ExecuteStatistics,ProcessAutoreports,OptimizeStatistics,AnalyseDomainStatistics,AnalyseClientStatistics,LoadCustomizations,UpdateApsCache,UpdateApsApplications,ExecuteGlCleaner,StoreProtectedConfigs,ExecuteWebStatistics,UpdatePhpCurlCertificates,ExecuteQuotacheck,BackupRestoreStats,UpgradeExtensions,ComposerSelfUpdate,AutoresponderEndDate >/dev/null 2>&1

Now, ever since doing the in-place upgrade to 17.8.11, the servers load explodes at night and the culprit appears to be the one (or more?) of these tasks. There's a ridiculous number of interface_async_executor.php processes running concurrently, few numbers:

grep '/usr/local/psa/admin/bin/event_handler -i -u psaadm /usr/local/psa/admin/bin/php -- -f /usr/local/psa/admin/plib/scripts/interface_async_executor.php' plesk-high-loadavg.plesk1 | wc -l
820

grep '/usr/local/psa/admin/bin/event_handler -i -u psaadm /usr/local/psa/admin/bin/php -- -f /usr/local/psa/admin/plib/scripts/interface_async_executor.php' plesk-high-loadavg.plesk2 | wc -l
580

They're all running the event handler. The truncated "top" output shows:
3658 root 30 10 13256 176 0 S 3.6 0.0 0:00.02 /usr/local/psa/admin/bin/event_handler -i -u psaadm /usr/local/psa/admin/bin/php -- -f /usr/local/psa/admin/plib/scripts/interface_async_executor.php -- EventListener /usr/local/psa/admin/plib/modules/dnssec/library/EventListener.php handleEvent admin -#-#- -u psaadm /usr/local/psa/admin/bin/php -- -f /usr/local/psa/admin/plib/scripts/interface_async_executor.php -- EventListener /usr/local/psa/admin/plib/modules/servershield/library/Even+

For every Plesk event we're running a handler that does some form of logging, here are the events run at the time when the top snapshot was taken, hundreds of them:
27529 root 30 10 13256 176 0 S 4.3 0.0 0:00.01 /usr/local/psa/admin/bin/event_handler -u root -- /usr/local/sbin/plesk-handler-logevent.sh -n actionlog__event_domain_status_update
326 root 30 10 13256 172 0 S 0.0 0.0 0:00.01 /usr/local/psa/admin/bin/event_handler -u root -- /usr/local/sbin/plesk-handler-logevent.sh -n actionlog__event_domain_guid_update
397 root 30 10 13256 172 0 S 0.0 0.0 0:00.00 /usr/local/psa/admin/bin/event_handler -u root -- /usr/local/sbin/plesk-handler-logevent.sh -n actionlog__event_domain_guid_update
406 root 30 10 13256 176 0 S 0.0 0.0 0:00.00 /usr/local/psa/admin/bin/event_handler -u root -- /usr/local/sbin/plesk-handler-logevent.sh -n actionlog__event_domain_guid_update
411 root 30 10 13256 176 0 S 0.0 0.0 0:00.00 /usr/local/psa/admin/bin/event_handler -u root -- /usr/local/sbin/plesk-handler-logevent.sh -n actionlog__event_domain_status_update
415 root 30 10 13256 176 0 S 0.0 0.0 0:00.00 /usr/local/psa/admin/bin/event_handler -u root -- /usr/local/sbin/plesk-handler-logevent.sh -n actionlog__event_domain_guid_update
419 root 30 10 13256 172 0 S 0.0 0.0 0:00.03 /usr/local/psa/admin/bin/event_handler -u root -- /usr/local/sbin/plesk-handler-logevent.sh -n actionlog__event_domain_status_update
424 root 30 10 13256 176 0 S 0.0 0.0 0:00.00 /usr/local/psa/admin/bin/event_handler -u root -- /usr/local/sbin/plesk-handler-logevent.sh -n actionlog__event_domain_guid_update
428 root 30 10 13256 172 0 S 0.0 0.0 0:00.00 /usr/local/psa/admin/bin/event_handler -u root -- /usr/local/sbin/plesk-handler-logevent.sh -n actionlog__event_domain_status_update
432 root 30 10 13256 172 0 S 0.0 0.0 0:00.02 /usr/local/psa/admin/bin/event_handler -u root -- /usr/local/sbin/plesk-handler-logevent.sh -n actionlog__event_domain_guid_update
442 root 30 10 13256 176 0 S 0.0 0.0 0:00.00 /usr/local/psa/admin/bin/event_handler -u root -- /usr/local/sbin/plesk-handler-logevent.sh -n actionlog__event_domain_guid_update
446 root 30 10 13256 176 0 S 0.0 0.0 0:00.00 /usr/local/psa/admin/bin/event_handler -u root -- /usr/local/sbin/plesk-handler-logevent.sh -n actionlog__event_domain_status_update
[...]

Why are these jobs run?

 

[burnley]

On a closer inspection of our logs it turns out Plesk runs these event handlers for every subscription:
server1:
actionlog__event_siteapp_upgrade - 64
actionlog__event_domain_guid_update - 869
actionlog__event_domain_status_update - 869

server2:
actionlog__event_siteapp_upgrade - 68
actionlog__event_domain_guid_update - 1256
actionlog__event_domain_status_update - 1256

server3 (fairly new, the least populated)
actionlog__event_siteapp_upgrade - 1
actionlog__event_domain_guid_update - 90
actionlog__event_domain_status_update - 90

server4:
actionlog__event_siteapp_upgrade - 28
actionlog__event_domain_guid_update - 714
actionlog__event_domain_status_update - 714

... and so on.

Our handler logs entries like these for the two most often executed events:

2019-06-07 01:28:17.070140 plesk-handler-logevent.sh [pid:27651] - Plesk event handler detected: [serverhostname: plesk.server][serverprimaryip: 192.168.0.300][serveruniqueid: 8c642ae1-ab90-5f0d-8d39-a63a91791c91][event: UNSET, UNUSED][eventhandler: actionlog__event_domain_guid_update][eventdata: {'PHP_IDE_CONFIG': '', 'NEW_STATUS': '', 'RANDOM_DELAY': '10', 'LOGNAME': 'root', 'OLD_GUID': '50f3e6e1-2928-402c-82ab-11a403e59693', 'PATH': '/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin', 'HOME': '/root', 'START_HOURS_RANGE': '0', 'NEW_CLIENT_GUID': 'd1a143f1-a0d8-4e45-a6a8-26aca798e916', 'MAILTO': 'root', 'SHELL': '/bin/sh', 'SHLVL': '8', 'NEW_EXTENDED_STATUS_OF_DOMAIN': '', 'NEW_DOMAIN_NAME': 'domain.com', 'OLD_EXTENDED_STATUS_OF_DOMAIN': '', 'OLD_STATUS': '', 'LANG': 'en_US.UTF-8', 'XDG_RUNTIME_DIR': '/run/user/0', 'NEW_DOMAIN_GUID': '50f3e6e1-2928-402c-82ab-11a403e59693', 'OLD_DOMAIN_NAME': 'domain.com', 'OLD_DOMAIN_GUID': '50f3e6e1-2928-402c-82ab-11a403e59693', 'XDG_SESSION_ID': '53576', 'NEW_GUID': '50f3e6e1-2928-402c-82ab-11a403e59693', '_': '/usr/local/psa/admin/bin/event_handler', 'PLESK_INTERNAL_PHP_EXEC': '', 'PWD': '/', 'OLD_CLIENT_GUID': 'd1a143f1-a0d8-4e45-a6a8-26aca798e916', 'USER': 'root'}]
2019-06-07 01:28:54.167665 plesk-handler-logevent.sh [pid:31735] - Plesk event handler detected: [serverhostname: plesk.server][serverprimaryip: 192.168.0.300][serveruniqueid: 8c642ae1-ab90-5f0d-8d39-a63a91791c91][event: UNSET, UNUSED][eventhandler: actionlog__event_domain_status_update][eventdata: {'PHP_IDE_CONFIG': '', 'NEW_STATUS': '0', 'RANDOM_DELAY': '10', 'LOGNAME': 'root', 'OLD_GUID': '', 'PATH': '/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin', 'HOME': '/root', 'START_HOURS_RANGE': '0', 'NEW_CLIENT_GUID': 'd1a143f1-a0d8-4e45-a6a8-26aca798e916', 'MAILTO': 'root', 'SHELL': '/bin/sh', 'SHLVL': '8', 'NEW_EXTENDED_STATUS_OF_DOMAIN': 'active', 'NEW_DOMAIN_NAME': 'domain.com', 'OLD_EXTENDED_STATUS_OF_DOMAIN': 'active', 'OLD_STATUS': '0', 'LANG': 'en_US.UTF-8', 'XDG_RUNTIME_DIR': '/run/user/0', 'NEW_DOMAIN_GUID': '50f3e6e1-2928-402c-82ab-11a403e59693', 'OLD_DOMAIN_NAME': 'domain.com', 'OLD_DOMAIN_GUID': '50f3e6e1-2928-402c-82ab-11a403e59693', 'XDG_SESSION_ID': '53576', 'NEW_GUID': '', '_': '/usr/local/psa/admin/bin/event_handler', 'PLESK_INTERNAL_PHP_EXEC': '', 'PWD': '/', 'OLD_CLIENT_GUID': 'd1a143f1-a0d8-4e45-a6a8-26aca798e916', 'USER': 'root'}]

 

[burnley]

This just keeps going, every night the load average on our servers explodes, sometimes to 650+, which is unacceptable. Check this out:
grep '/usr/local/psa/admin/bin/event_handler -i -u psaadm /usr/local/psa/admin/bin/php -- -f /usr/local/psa/admin/plib/scripts/interface_async_executor.php -- EventListener /usr/local/psa/admin/plib/modules/servershield/library/EventListener.php handleEvent admin -#-#-' /tmp/1.out | wc -l

More than 2100 such processes. Which is the task running these? We muststop this mess, really.

 

[burnley]

Submitted as a bug:
Plesk 17.8.11, upgraded from 17.5.3: high load average caused by /etc/cron.daily/50plesk-daily
It keeps happening and we find it unacceptable.

 

[sebgonzes]

Submitted as a bug:
Plesk 17.8.11, upgraded from 17.5.3: high load average caused by /etc/cron.daily/50plesk-daily
It keeps happening and we find it unacceptable.

Try to disable ExecuteSpamtrain filter, it's usually an very heavy process.