[BUG]: high MySQL load through unterminated cronjobs

mokkin commented 11 months ago

⚠️ This issue respects the following points: ⚠️

[X] This is a single bug, not a question or a configuration/webserver/proxy issue.
[X] This is not a bug in the browser extension or another client.
[X] This issue is not already reported on Github (I've searched it).
[X] Nextcloud Server and the Passwords App is up to date. See Nextcloud Apps.
[X] There are no warnings and errors reported in the Passwords App settings in the admin area
[X] The following apps are not installed: Rainloop

Server Information

{
    "version": {
        "server": "27.0.1.2",
        "app": "2023.8.31",
        "lsr": false,
        "php": "8.2.8",
        "cronPhp": "8.2.8"
    },
    "environment": {
        "os": "Linux",
        "architecture": "x86_64",
        "bits": 64,
        "database": "mysql",
        "cron": "cron",
        "proxy": false,
        "sslProxy": false,
        "subdirectory": false
    },
    "services": {
        "images": "imagick",
        "favicons": "ddg",
        "previews": "default",
        "security": "hibp",
        "words": "auto",
        "previewApi": false,
        "faviconApi": false
    },
    "status": {
        "autoBackupRestored": false
    },
    "settings": {
        "channel": "stable",
        "nightlies": false,
        "handbook": false,
        "performance": 5
    },
    "encryption": {
        "sse": {
            "SSEv1r1": false,
            "SSEv1r2": true,
            "SSEv2r1": false,
            "SSEv3r1": false,
            "none": false,
            "default": "SSEv1r2"
        },
        "cse": {
            "CSEv1r1": false,
            "none": true,
            "default": "none"
        }
    }
}

Client Information

Browser and Version: Firefox 116.0 Client OS and Version: Ubuntu 22.04

Bug description

Please cross check https://github.com/nextcloud/server/issues/39648

I already reported it there. After disabling passwords and rebooting no abondended cronjobs appear even after 12 hours. Right after enabling it again, the abondended cronjobs are back.

Steps to reproduce

enable passwords
check nextcloud log
check htop

Expected behavior

cronjobs terminating regularly, no high db load

Nextcloud Logs

[passwords] Fatal: OCP\AppFramework\Db\DoesNotExistException: Did expect one result but found none when executing: query "SELECT `a`.* FROM `*PREFIX*passwords_password_rv` `a` INNER JOIN `*PREFIX*passwords_password` `b` ON a.`model` = b.`uuid` WHERE (`a`.`deleted` = :dcValue1) AND (`b`.`user_id` = `a`.`user_id`) AND (`b`.`revision` = `a`.`uuid`) AND (`b`.`uuid` = :dcValue2)";  at <<closure>>

0. /var/www/nextcloud/lib/public/AppFramework/Db/QBMapper.php line 361
   OCP\AppFramework\Db\QBMapper->findOneQuery()
1. /var/www/nextcloud/apps/passwords/lib/Db/AbstractRevisionMapper.php line 69
   OCP\AppFramework\Db\QBMapper->findEntity()
2. /var/www/nextcloud/apps/passwords/lib/Services/Object/AbstractRevisionService.php line 172
   OCA\Passwords\Db\AbstractRevisionMapper->findCurrentRevisionByModel()
3. /var/www/nextcloud/apps/passwords/lib/Cron/SynchronizeShares.php line 172
   OCA\Passwords\Services\Object\AbstractRevisionService->findCurrentRevisionByModel()
4. /var/www/nextcloud/apps/passwords/lib/Cron/SynchronizeShares.php line 83
   OCA\Passwords\Cron\SynchronizeShares->createNewShares("*** sensitive parameters replaced ***")
5. /var/www/nextcloud/apps/passwords/lib/Cron/AbstractTimedJob.php line 59
   OCA\Passwords\Cron\SynchronizeShares->runJob()
6. /var/www/nextcloud/lib/public/BackgroundJob/Job.php line 86
   OCA\Passwords\Cron\AbstractTimedJob->run()
7. /var/www/nextcloud/lib/public/BackgroundJob/TimedJob.php line 103
   OCP\BackgroundJob\Job->start()
8. /var/www/nextcloud/lib/public/BackgroundJob/TimedJob.php line 93
   OCP\BackgroundJob\TimedJob->start()
9. /var/www/nextcloud/cron.php line 152
   OCP\BackgroundJob\TimedJob->execute()

at 2023-08-03T14:20:02+02:00

Browser Logs

No response

marius-wieschollek commented 11 months ago

I can't really see how a not found database entry would cause so much load. Do you have any errors such as "Could not create target password from […]" in your log or just this one? Also, how many shares and passwords are on your system and what execution duration does SELECT * FROMoc_jobsWHEREclassLIKE '%Passwords%SynchronizeShares%' report?

mokkin commented 11 months ago

I can't really see how a not found database entry would cause so much load. Do you have any errors such as "Could not create target password from […]" in your log or just this one?

Now only once, because I rebooted the server before. But before the reboot this message occured like three or four times per day I guess.

Also, how many shares and passwords are on your system

You mean all the shares in Nextcloud from /settings/admin/serverinfo ?

Users: 124 Groups: 11 Links: 155 Emails: 22 Talk conversations: 388

what execution duration does SELECT * FROM oc_jobsWHEREclassLIKE '%Passwords%SynchronizeShares%' report?

MariaDB [nextcloud]> SELECT * FROM oc_jobs WHERE class LIKE '%Passwords%SynchronizeShares%';
+-------+--------------------------------------+----------+------------+--------------+-------------+--------------------+----------------------------------+----------------+
| id    | class                                | argument | last_run   | last_checked | reserved_at | execution_duration | argument_hash                    | time_sensitive |
+-------+--------------------------------------+----------+------------+--------------+-------------+--------------------+----------------------------------+----------------+
| 71734 | OCA\Passwords\Cron\SynchronizeShares | null     | 1691065202 |   1691065202 |  1691065202 |                  0 | 37a6259cc0c1dae299a7866489dff0bd |              1 |
+-------+--------------------------------------+----------+------------+--------------+-------------+--------------------+----------------------------------+----------------+
1 row in set (0,000 sec)

marius-wieschollek commented 11 months ago

As far as i can see, there seems to be one defective share where the password that was shared does no longer exist. That can be fixed with ./occ maintenance:repair. But it also isn't something that causes high load since the server just skips that share and continues with the rest.

The count of shares in Passwords isn't in the server info, you can get it with

SELECT COUNT(*) FROM `oc_passwords_share`

and for passwords with

SELECT COUNT(*) FROM `oc_passwords_password`

I wonder if it's maybe just a lot of shares which need to be synchronized or if maybe there is a loop somewhere which causes an endless update of passwords.

mokkin commented 11 months ago

Thanks for the repair command. I didn't know this yet ;)

Here are the shares:

MariaDB [nextcloud]> SELECT COUNT(*) FROM `oc_passwords_share`;
+----------+
| COUNT(*) |
+----------+
|       92 |
+----------+
1 row in set (0,000 sec)

MariaDB [nextcloud]> SELECT COUNT(*) FROM `oc_passwords_password`;
+----------+
| COUNT(*) |
+----------+
|      382 |
+----------+
1 row in set (0,001 sec)

I will enable passwords again now.

mokkin commented 11 months ago

Right after re-enabling passwords the first cronjob is getting an infinite one with high load again :(

mokkin commented 11 months ago

The same log entry is back as well:

[passwords] Fatal: OCP\AppFramework\Db\DoesNotExistException: Did expect one result but found none when executing: query "SELECT `a`.* FROM `*PREFIX*passwords_password_rv` `a` INNER JOIN `*PREFIX*passwords_password` `b` ON a.`model` = b.`uuid` WHERE (`a`.`deleted` = :dcValue1) AND (`b`.`user_id` = `a`.`user_id`) AND (`b`.`revision` = `a`.`uuid`) AND (`b`.`uuid` = :dcValue2)";  at <<closure>>

0. /var/www/nextcloud/lib/public/AppFramework/Db/QBMapper.php line 361
   OCP\AppFramework\Db\QBMapper->findOneQuery()
1. /var/www/nextcloud/apps/passwords/lib/Db/AbstractRevisionMapper.php line 69
   OCP\AppFramework\Db\QBMapper->findEntity()
2. /var/www/nextcloud/apps/passwords/lib/Services/Object/AbstractRevisionService.php line 172
   OCA\Passwords\Db\AbstractRevisionMapper->findCurrentRevisionByModel()
3. /var/www/nextcloud/apps/passwords/lib/Cron/SynchronizeShares.php line 172
   OCA\Passwords\Services\Object\AbstractRevisionService->findCurrentRevisionByModel()
4. /var/www/nextcloud/apps/passwords/lib/Cron/SynchronizeShares.php line 83
   OCA\Passwords\Cron\SynchronizeShares->createNewShares("*** sensitive parameters replaced ***")
5. /var/www/nextcloud/apps/passwords/lib/Cron/AbstractTimedJob.php line 59
   OCA\Passwords\Cron\SynchronizeShares->runJob()
6. /var/www/nextcloud/lib/public/BackgroundJob/Job.php line 86
   OCA\Passwords\Cron\AbstractTimedJob->run()
7. /var/www/nextcloud/lib/public/BackgroundJob/TimedJob.php line 103
   OCP\BackgroundJob\Job->start()
8. /var/www/nextcloud/lib/public/BackgroundJob/TimedJob.php line 93
   OCP\BackgroundJob\TimedJob->start()
9. /var/www/nextcloud/cron.php line 152
   OCP\BackgroundJob\TimedJob->execute()

at 2023-08-04T13:05:02+02:00

{"reqId":"ekMtefFftR7uy2mChuAr","level":4,"time":"2023-08-04T13:05:02+02:00","remoteAddr":"","user":"--","app":"passwords","method":"","url":"--","message":"Could not create target password from 8b8baf21-7d7f-4a78-8818-d42074a11055 for share a27e6776-3116-4022-9ca9-ad5d56a1f10d: Did expect one result but found none when executing: query \"SELECT `a`.* FROM `*PREFIX*passwords_password_rv` `a` INNER JOIN `*PREFIX*passwords_password` `b` ON a.`model` = b.`uuid` WHERE (`a`.`deleted` = :dcValue1) AND (`b`.`user_id` = `a`.`user_id`) AND (`b`.`revision` = `a`.`uuid`) AND (`b`.`uuid` = :dcValue2)\"; ","userAgent":"--","version":"27.0.1.2","exception":{"Exception":"OCP\\AppFramework\\Db\\DoesNotExistException","Message":"Did expect one result but found none when executing: query \"SELECT `a`.* FROM `*PREFIX*passwords_password_rv` `a` INNER JOIN `*PREFIX*passwords_password` `b` ON a.`model` = b.`uuid` WHERE (`a`.`deleted` = :dcValue1) AND (`b`.`user_id` = `a`.`user_id`) AND (`b`.`revision` = `a`.`uuid`) AND (`b`.`uuid` = :dcValue2)\"; ","Code":0,"Trace":[{"file":"/var/www/nextcloud/lib/public/AppFramework/Db/QBMapper.php","line":361,"function":"findOneQuery","class":"OCP\\AppFramework\\Db\\QBMapper","type":"->"},{"file":"/var/www/nextcloud/apps/passwords/lib/Db/AbstractRevisionMapper.php","line":69,"function":"findEntity","class":"OCP\\AppFramework\\Db\\QBMapper","type":"->"},{"file":"/var/www/nextcloud/apps/passwords/lib/Services/Object/AbstractRevisionService.php","line":172,"function":"findCurrentRevisionByModel","class":"OCA\\Passwords\\Db\\AbstractRevisionMapper","type":"->"},{"file":"/var/www/nextcloud/apps/passwords/lib/Cron/SynchronizeShares.php","line":172,"function":"findCurrentRevisionByModel","class":"OCA\\Passwords\\Services\\Object\\AbstractRevisionService","type":"->"},{"file":"/var/www/nextcloud/apps/passwords/lib/Cron/SynchronizeShares.php","line":83,"function":"createNewShares","class":"OCA\\Passwords\\Cron\\SynchronizeShares","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"/var/www/nextcloud/apps/passwords/lib/Cron/AbstractTimedJob.php","line":59,"function":"runJob","class":"OCA\\Passwords\\Cron\\SynchronizeShares","type":"->"},{"file":"/var/www/nextcloud/lib/public/BackgroundJob/Job.php","line":86,"function":"run","class":"OCA\\Passwords\\Cron\\AbstractTimedJob","type":"->"},{"file":"/var/www/nextcloud/lib/public/BackgroundJob/TimedJob.php","line":103,"function":"start","class":"OCP\\BackgroundJob\\Job","type":"->"},{"file":"/var/www/nextcloud/lib/public/BackgroundJob/TimedJob.php","line":93,"function":"start","class":"OCP\\BackgroundJob\\TimedJob","type":"->"},{"file":"/var/www/nextcloud/cron.php","line":152,"function":"execute","class":"OCP\\BackgroundJob\\TimedJob","type":"->"}],"File":"/var/www/nextcloud/lib/public/AppFramework/Db/QBMapper.php","Line":283,"message":"Could not create target password from 8b8baf21-7d7f-4a78-8818-d42074a11055 for share a27e6776-3116-4022-9ca9-ad5d56a1f10d: Did expect one result but found none when executing: query \"SELECT `a`.* FROM `*PREFIX*passwords_password_rv` `a` INNER JOIN `*PREFIX*passwords_password` `b` ON a.`model` = b.`uuid` WHERE (`a`.`deleted` = :dcValue1) AND (`b`.`user_id` = `a`.`user_id`) AND (`b`.`revision` = `a`.`uuid`) AND (`b`.`uuid` = :dcValue2)\"; ","exception":[],"CustomMessage":"Could not create target password from 8b8baf21-7d7f-4a78-8818-d42074a11055 for share a27e6776-3116-4022-9ca9-ad5d56a1f10d: Did expect one result but found none when executing: query \"SELECT `a`.* FROM `*PREFIX*passwords_password_rv` `a` INNER JOIN `*PREFIX*passwords_password` `b` ON a.`model` = b.`uuid` WHERE (`a`.`deleted` = :dcValue1) AND (`b`.`user_id` = `a`.`user_id`) AND (`b`.`revision` = `a`.`uuid`) AND (`b`.`uuid` = :dcValue2)\"; "},"id":"64ccf97cb8a03"}

mokkin commented 11 months ago

I checked the log and processes again. Since reenabling passwords today there are exactly two log entries like posted above and exactly two unterminated high load cronjobs running. There seems to be definitely a connection.

grafik

marius-wieschollek commented 11 months ago

I think the issue might be that there is some circular share situation where the job can never finish because there is always an updated password. I have published a nightly version which has a limit for how many attempts to synchronize passwords the job makes. You can try if this fixes the issue.

marius-wieschollek commented 11 months ago

You can try checking the count of revisions with

SELECT COUNT(*) FROM `oc_passwords_password_rv`;

If the count is much higher than the 382 passwords you have, it's probably that.

mokkin commented 11 months ago

Probably you are right:

MariaDB [nextcloud]> SELECT COUNT(*) FROM `oc_passwords_password_rv`;
+----------+
| COUNT(*) |
+----------+
|      669 |
+----------+
1 row in set (0,001 sec)

mokkin commented 11 months ago

I have published a nightly version which has a limit for how many attempts to synchronize passwords the job makes. You can try if this fixes the issue.

Perfect! Thank you very much! Immediately it has fixed the issue and even terminated the pending cronjobs.

marius-wieschollek / passwords