Upgrading Nextcloud sometimes causes Cronjob Deadlocks

[BernhardPosselt]

Sometimes when upgrading Nextcloud, the reserved_at attribute for cronjobs is set to a value that will never be triggered. This causes the News cronjob to never run. You can check if that happens by executing

SELECT reserved_at FROM oc_jobs WHERE argument = '["OCA\\News\\Cron\\Updater","run"]' AND reserved_at <> 0;

Then you have to manually reset it using

UPDATE oc_jobs SET reserved_at = 0 WHERE argument = '["OCA\\News\\Cron\\Updater","run"]';

My guess is that it's caused by a race condition (maybe we should prevent updating when a cronjob is run?)

[sphrak]

• moved comment here as per [Observation] Additional reasons feeds might stop working - and other things (Not a news app bug) news#148

I am writing this as an experience I had and how I solved it to help others solve this issue aswell - and perhaps inspire some sort of check to prevent this from actually ever happen or at least some information about this in wiki.

• I am posting it in news since this was mainly the app I had trouble with - only later I realized it affected other parts of nextcloud aswell.

Problem - feeds not updating?

For some months after a server hardware upgrade I noticed that my feed stopped working all of a sudden.

After reading through the README.md on what can cause this I couldnt figure out why it stopped all of a sudden, I uninstalled the app, upgraded nextcloud etc etc but nothing worked. However I could launch a new instance of nextcloud and that would work with the feeds I got (subscription.opml).

So after digging around I found this in the oc_jobs, OC\BackgroundJob\Legacy\RegularJob with argument ["OCA\\News\\Cron\\Updater","run"]. This all looked good but the last_checked and last_run had a big difference in epoch time, where most where last ran at 1494480602
With a last updated epoch time of 1507129203, which is Wed, 04 Oct 2017 15:00:03 GMT.

While at this I also noticed something I hadnt paid attention to, I had not recieved any email notifications of uploads either. Again the last_checked and last_run where epoch 1507129201 so again way ahead of actual time. Thus not executing.

Solution

Not recommended way

So I simply deleted the entries in oc_jobs and disabled the apps, uninstalled it - and reinstalled and added back my feeds and now it works again.

Recommended way

But probably the better way to do it is just to update the last_run and last_checked to a time that has passed already - instead of deleting it.

Conclusion

So what I think happened was that the time and date where incorrect when I first booted up the new hardware and somehow it managed
to run those scripts before I noticed and was able to change it - since everything else behaived in a fashion one would expect. Except news and email notifications - but this fixes it.

• I also ran maintenance:repair just to be sure aswell but it didnt seem to do anything regarding this issue.

Kind regards,
sphrak

[sphrak]

PS. I cant find this solution in FAQ (am I blind?) - it seems only to talk about this:

DELETE FROM oc_appconfig WHERE appid = 'news';
DROP TABLE oc_news_items;
DROP TABLE oc_news_feeds;
DROP TABLE oc_news_folders;

and checking that

SELECT reserved_at FROM oc_jobs WHERE argument = '["OCA\\News\\Cron\\Updater","run"]';

returns a zero value and in my case it did.

However the last_run and last_checked was way ahead of present time due to previously stated issue with incorrect system time.

Another suggested and perhaps cleaner solution could be:

UPDATE oc_jobs SET last_checked = 0 WHERE argument = '["OCA\\News\\Cron\\Updater","run"]';
UPDATE oc_jobs SET last_run = 0 WHERE argument = '["OCA\\News\\Cron\\Updater","run"]';

Then upon next execution of cron.php - both last_checked and last_run will have correct timestamp again.

Cheers

[juliushaertl]

This also happened to me while developing some feature for the deck app. In my case there was a runtime error causing the cronjob to stop. In that case the cronjob reserved_at value is set and it will never be called again.

In my case you can see in the log files that the job never finished because of the error:

Fatal | cron | Call to a member function get() on null 
Debug | cron | Run OCA\Deck\Cron\ScheduledNotifications job with ID 26 

I've not digged into the job/cron code yet, but maybe it helps to just clear the reserved_at value at least when the app updates.

[juliushaertl]

Ah nevermind, I just ran into a lock of 12 hours as described here: #2382 (comment)

[FriedCircuits]

I recently had the same issue. Resetting requested_at to 0 worked and feeds are syncing again. This was in Postgres.

[skjnldsv]

I think we fixed it now.

[returntrip]

I got this issue recently (in the last 2 weeks), the News app stopped working then I set reserved_at to 0 and feeds started updating again. But I have noticed that now reserved_at is set to a value different than 0. Is this an issue with my setup?

MariaDB [nextcloud]> SELECT reserved_at FROM jobs WHERE (argument = '["OCA\\News
\\Cron\\Updater","run"]' OR class = 'OCA\\News\\Cron\\Updater');
+-------------+
| reserved_at |
+-------------+
|  1568619001 |
+-------------+
1 row in set (0.001 sec)

and

MariaDB [nextcloud]> UPDATE jobs SET reserved_at = 0 WHERE (argument = '["OCA\\N
ews\\Cron\\Updater","run"]' OR class = 'OCA\\News\\Cron\\Updater');
Query OK, 1 row affected (0.060 sec)
Rows matched: 1  Changed: 1  Warnings: 0