Log full of mysterious "Unexpected error when updating feed More than one result" messages -> improve error messages for update process

[blizzz]

Explain the Problem

The message »Unexpected error when updating feed More than one result« is logged with every cron run. Neither it is clear what is wrong, and what should be done.

Steps to Reproduce

Explain what you did to encounter the issue

1. Upgrade OC to 9.0 and News app to 7.1.2
2. Normal usage

   System Information

   • News app version: 7.1.2
   • ownCloud version: 9.0.0
   • PHP version: 5.5.9
   • Database and version: mysql Ver 14.14 Distrib 5.5.47
   • Browser and version: n/a
   • Distribution and version: Ubuntu 14.04

     Contents of owncloud/data/owncloud.log

…
{"reqId":"FmwjTMkHKCNjjAg4k9Ng","remoteAddr":"","app":"news","message":"Unexpected error when updating feed More than one result","level":3,"time":"2016-03-13T22:30:52+00:00"}
{"reqId":"iXV+la7h1q2+o5iqHR4T","remoteAddr":"","app":"news","message":"Unexpected error when updating feed More than one result","level":3,"time":"2016-03-13T22:35:57+00:00"}
{"reqId":"4YpRUfitEzTaZILusypC","remoteAddr":"","app":"news","message":"Unexpected error when updating feed More than one result","level":3,"time":"2016-03-13T22:40:56+00:00"}
…

[BernhardPosselt]

Logged here: https://github.com/owncloud/news/blob/master/service/feedservice.php#L164

Basically means that any find in the update method which should only ever return one result returned two (no stacktrace, can you maybe create a PR to also log the trace? http://php.net/manual/en/exception.gettraceasstring.php)

This is likely a result of a bad db migration and nothing that can be solved on my side. What you can do:

• get the trace
• find out which find method threw the exception
• check which database table contains the unique violations
• delete the duplicates

[blizzz]

@BernhardPosselt thanks for these steps.

The trace is:

#0 /path/to/owncloud/lib/public/appframework/db/mapper.php(347): OCP\AppFramework\Db\Mapper->findOneQuery('SELECT `items`....', Array, NULL, NULL)
#1 /path/to/apps-extra/news/db/itemmapper.php(265): OCP\AppFramework\Db\Mapper->findEntity('SELECT `items`....', Array)
#2 /path/to/apps-extra/news/service/feedservice.php(235): OCA\News\Db\ItemMapper->findByGuidHash('378038c6341686e...', 87, '$USER')
#3 /path/to/apps-extra/news/service/feedservice.php(161): OCA\News\Service\FeedService->update(87, '$USER')
#4 /path/to/apps-extra/news/utility/updater.php(45): OCA\News\Service\FeedService->updateAll()
#5 /path/to/apps-extra/news/cron/updater.php(32): OCA\News\Utility\Updater->update()
#6 [internal function]: OCA\News\Cron\Updater::run()
#7 /path/to/owncloud/lib/private/backgroundjob/legacy/regularjob.php(28): call_user_func(Array)
#8 /path/to/owncloud/lib/private/backgroundjob/job.php(52): OC\BackgroundJob\Legacy\RegularJob->run(Array)
#9 /path/to/owncloud/cron.php(141): OC\BackgroundJob\Job->execute(Object(OC\BackgroundJob\JobList), Object(OC\Log))
#10 {main}

There are indeed two entries in the news_items table having the same guid, guid_hash, feed_id, url and title.

select distinct guid from news_items; returns 9703 rows, while in total there are 9996 rows. Roughly 300 dups, apparently.

[BernhardPosselt]

Is this issue resolved? Do you feel that the stacktrace should be added in the log? If so, could you create a PR?

[blizzz]

Not resolved, if I need to do it manually. I did not do it for the other 300 entries, yet. Might look into it, but not much time right now.

[BernhardPosselt]

If it's a bug, it's in core because I don't touch migrations ;)

[BernhardPosselt]

Quick guess: cronjobs are run while the database schema is being migrated.

[blizzz]

If it's a bug, it's in core because I don't touch migrations ;)

OK. At least returning the feed id would be helpful.

Quick guess: cronjobs are run while the database schema is being migrated.

I really hope it does not run in maintenance mode :) yet need to verify.

[BernhardPosselt]

Will improve the error messages ;)

As for the cronjob: what happens if a cronjob is running 1 hour and needs another hour to finish and then ownCloud goes into maintenance mode? Is the cronjob killed? Does it wait with the update until the cronjob is finished?

[BernhardPosselt]

Moved to https://github.com/owncloud/core/pull/23712